Performance regression in 'IsTypedBy'

[andreinovikovsiemens]

Starting with version 6.0.442, calling 'IsTypedBy' for IIfcElement takes significantly more time when working with relatively large models.

I prepared simple projects with similar console applications, but different versions of xbim as dependencies.

IsTypedByRegressionCheck.zip

How to reproduce:

1. Download and open the attached solution in Visual Studio.
2. Set Example_5_1_341 as the startup project.
3. In the project settings (Debug section), add the path to the IFC file to the command line arguments. (e.g., NBU_MedicalClinic_Eng-MEP.ifc from this link).
4. Run the project.
5. Set Example_6_0_442 as the startup project.
6. Add the same IFC file path to the command line arguments for this project.
7. Run the project.
8. Compare the results.
   Example output:

Hello xbim!
Example_5_1_341, file name: NBU_MedicalClinic_Eng-MEP.ifc
ifc store ready
total elements count: 16012
elements with type count: 16012
open store time: 12.2334502
process elements time: 0.06461

Hello xbim!
Example_6_0_442, file name: NBU_MedicalClinic_Eng-MEP.ifc
ifc store ready
total elements count: 16012
elements with type count: 16012
open store time: 34.6255213
process elements time: 14.0791487

As of my results from my laptop it was 0.06461 s in project with dependency on xbim 5.1.341 against 14.0791487 s in project with dependency on xbim 6.0.442
As of my tests with updated xbim - newer versions of xbim performing in relative same time as 6.0.442

---

Here is code from attached project just in case

public class Program
{
    public static void Main(string[] args)
    {
        Console.WriteLine("Hello xbim!");
        Console.WriteLine(string.Format("Example_5_1_341, file name: {0}", Path.GetFileName(args[0])));

        string filePath = args[0];

        Stopwatch openStoreStopwatch = new Stopwatch();
        Stopwatch processElementsStopwatch = new Stopwatch();
        openStoreStopwatch.Start();
        using (IfcStore ifcStore = IfcStore.Open(args[0]))
        {
            openStoreStopwatch.Stop();
            Console.WriteLine("ifc store ready");
            using (var inverseCache = ifcStore.BeginInverseCaching())
            {
                processElementsStopwatch.Start();
                var elements = ifcStore.Instances.OfType<IIfcElement>().ToList();

                int typedElementsCount = 0;
                Console.WriteLine(string.Format("total elements count: {0}", elements.Count));
                foreach (var element in elements)
                {
                    var typedDefault = element.IsTypedBy.FirstOrDefault();
                    if (typedDefault == null || typedDefault.RelatingType == null 
                        || typedDefault.RelatingType.Name == null || !typedDefault.RelatingType.Name.HasValue)
                    {
                        continue;
                    }

                    typedElementsCount++;
                }
                processElementsStopwatch.Stop();
                Console.WriteLine(string.Format("elements with type count: {0}", typedElementsCount));
            }
        }

        Console.WriteLine(string.Format("open store time: {0}", openStoreStopwatch.Elapsed.TotalSeconds.ToString()));
        Console.WriteLine(string.Format("process elements time: {0}", processElementsStopwatch.Elapsed.TotalSeconds.ToString()));

    }
}

[andyward]

I doubt it's specific to IsTypedBy as this won't have changed with the IFC Schemas.

My guess is this issue is similar to #665. That Clinical MEP model is 200MB+ of IFCSPF so would normally try to use Esent as the Model backing provider in the IfcStore.

However I don't see any explicit declaration of IfcStore.ModelProviderFactory.UseHeuristicModelProvider(); in the v5 code (which sets this up), so the system will use the InMemory model provider and not Esent - even when larger IFC files are used. In v6 the new DI system will auto register the Esent model provider when supported (which is essentially all Windows platforms now, netfx and net core). See the upgrade note in the Readme

Esent has an overhead in both opening a model first time, and in I/O (since data is just-in-time loaded during activation).

The memory model will generally be quicker to use for smaller models at the expense of more RAM usage over Esent. That's the trade off. Esent is costly to create (one time) but supports 'random access' without loading the whole model into memory (but also requires some caching for certain access patterns to achieve equivalent performance)

You may be able to improve Esent performance by adding using (var entityCache = ifcStore.BeginEntityCaching()) as well as BeginInverseCaching()

Can you confirm my theory by adding the UseHeuristicModelProvider() statement at the start of the program?

[andreinovikovsiemens]

Hi @andyward it seems using IfcStore.ModelProviderFactory.UseHeuristicModelProvider(); don't have significant impact on performance.

Hello xbim!
Example_6_0_442, file name: NBU_MedicalClinic_Eng-MEP.ifc
ifc store ready
total elements count: 16012
elements with type count: 16012
open store time: 33.3569727
process elements time: 10.4058399

Hello xbim!
Example_6_0_442, file name: NBU_MedicalClinic_Eng-MEP.ifc
applying IfcStore.ModelProviderFactory.UseHeuristicModelProvider()
ifc store ready
total elements count: 16012
elements with type count: 16012
open store time: 27.3990045
process elements time: 10.4611266

internal class Program
{
    public static void Main(string[] args)
    {
        Console.WriteLine("Hello xbim!");
        Console.WriteLine(string.Format("Example_6_0_442, file name: {0}", Path.GetFileName(args[0])));

        string filePath = args[0];

        Stopwatch openStoreStopwatch = new Stopwatch();
        Stopwatch processElementsStopwatch = new Stopwatch();
        openStoreStopwatch.Start();
#if HEURISTIC_MODEL_PROVIDER
        Console.WriteLine("applying IfcStore.ModelProviderFactory.UseHeuristicModelProvider()");
        IfcStore.ModelProviderFactory.UseHeuristicModelProvider();
#endif

        using (IfcStore ifcStore = IfcStore.Open(args[0]))
        {
            openStoreStopwatch.Stop();
            Console.WriteLine("ifc store ready");
            using (var inverseCache = ifcStore.BeginInverseCaching())
            //using (var cache = ifcStore.BeginEntityCaching())
            {
                processElementsStopwatch.Start();
                var elements = ifcStore.Instances.OfType<IIfcElement>().ToList();

                int typedElementsCount = 0;
                Console.WriteLine(string.Format("total elements count: {0}", elements.Count));
                foreach (var element in elements)
                {
                    var typedDefault = element.IsTypedBy.FirstOrDefault();
                    if (typedDefault == null || typedDefault.RelatingType == null
                        || typedDefault.RelatingType.Name == null || !typedDefault.RelatingType.Name.HasValue)
                    {
                        continue;
                    }

                    typedElementsCount++;
                }
                processElementsStopwatch.Stop();
                Console.WriteLine(string.Format("elements with type count: {0}", typedElementsCount));
            }
        }

        Console.WriteLine(string.Format("open store time: {0}", openStoreStopwatch.Elapsed.TotalSeconds.ToString()));
        Console.WriteLine(string.Format("process elements time: {0}", processElementsStopwatch.Elapsed.TotalSeconds.ToString()));

    }
}

My guts feeling that it is sort of miss-caching issue. On much larger IFC files besides of increased processing time we have significant overconsumption of system memory using various 'Inverse' api such as IsTypedBy, ContainedInStructure, IsDefinedBy.
I think system cannot find objects in existing cache even if it was red before and re-reads it adding to the cache second time.