performance profiling of first load of trace data #9465

mjkkirschner · 2019-01-31T20:58:31Z

Purpose

Element binding is very slow on first run when the size of the element binding data is greater than a few entires.

This change attempts to avoid the exponential cost of looping over all types in all assemblies to find a matching type name - instead we first try to look in assemblies that match in name only, then fallback to our slow matching strategy.

you can see in the below timeline profile that running the sample graph on first load took ~2.5 minutes and after this change runtime is ~25 seconds.

before:

after:

TODO:

add tests

Declarations

Check these if you believe they are true

The code base is in a better state after this PR
Is documented according to the standards
The level of testing this PR includes is appropriate
User facing strings, if any, are extracted into *.resx files
All tests pass using the self-service CI.
Snapshot of UI changes, if any.
Changes to the API follow Semantic Versioning, and are documented in the API Changes document.

Reviewers

@aparajit-pratap
@saintentropy

FYIs

@smangarole

src/Engine/ProtoCore/Lang/CallSite.cs

aparajit-pratap · 2019-02-01T18:58:50Z

@mjkkirschner I've added a test.

mjkkirschner · 2019-02-04T20:03:03Z

@aparajit-pratap thanks! I will build on top of this test with a large element binding example of the scale which replicates the issue.

src/Engine/ProtoCore/Lang/CallSite.cs

…ynamo into speedUpBindToType

add new test file with 1500 trace elements make traceBinder internal expose protoCore internals to dynamoCoreTests

mjkkirschner · 2019-02-06T01:49:32Z

@saintentropy @aparajit-pratap @QilongTang I have done the following:

re-enabled the existing callsite tests that were marked failure after getting them to pass
added traceBinder unit tests
added a perf test that asserts loading trace data for 1500 elements is accomplished in < 20 seconds. Currently this takes ~~2 seconds after this pr with my local set of assemblies.

PTAL

aparajit-pratap · 2019-02-06T03:57:21Z

test/DynamoCoreTests/CallsiteTests.cs

+
+            BeginRun();
+            sw.Stop();
+            Assert.Less(sw.Elapsed.Milliseconds, 20000);


How much time would this take earlier, 20s? This time could be hardware specific. I don't think it takes 20s for me without your fixes.

I will check - with the sample files I was using with similar sized data it took 2.5 minutes.

Sorry, it took over a min when I ran it again. I might have made a mistake running it the first time. It looked a lot faster then. I think testing for <20s shouldn't be a problem on most machines if you claim that it actually takes just 2s.

I'm curious what the existing tests tested (the ones you re-enabled)? LGTM!

The tests also do some really simple element binding and element disposal testing.

mjkkirschner · 2019-02-06T17:09:24Z

@aparajit-pratap on my vm - the loading of trace in this test takes 34 seconds before the change, after it takes 1.1 seconds - I ran them both a few times, this appears to be the average on my machine.

dimven · 2019-02-08T06:46:08Z

@mjkkirschner while these changes are great and will improve the deserialization of all kinds of custom classes that people have decided to save to their dynamo graph, isn't serializing the entire wrapped object for each bound element too much? I was just wondering if a special and more light-weight method could be implemented for those cases, one that stores only the unique id of the element as a string? Right now every public member of the wrapped object will get serialized, when all we need is the guid. All other parameters might have changed between the time the graph was saved last and the latest version of the Revit model it was used with and that would most likely invalidate the trace data.

If that's viable, it could hopefully improve both the robustness and the performance of element binding in general.

mjkkirschner · 2019-02-15T04:23:03Z

Hi @dimven Right now every public member of the wrapped object will get serialized, when all we need is the guid. this is not the case - in trace we only serialize the serializeableID class which is usually just an id - Directshapes serialize a bit more info. Unfortunately this uses SOAP formatter serialization which serializes a bunch of other info required for deserialization based on specific assembly version etc. The data is also base 64 encoded which actually makes it larger...

So your initial point is definitely valid, it's just maybe not as bad initially - or bad in other ways 😄 .

You can see what's in trace by base64 decoding it, and then base 64 decoding the individual elements again.

dimven · 2019-02-15T05:15:13Z

Thanks for shining a light of things. A single element serializes to this:

<SOAP-ENV:Envelope xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:SOAP-ENC="http://schemas.xmlsoap.org/soap/encoding/" xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/" xmlns:clr="http://schemas.microsoft.com/soap/encoding/clr/1.0" SOAP-ENV:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<SOAP-ENV:Body>
<a1:SerializableId id="ref-1" xmlns:a1="http://schemas.microsoft.com/clr/nsassem/RevitServices.Persistence/RevitServices%2C%20Version%3D2.0.2.6833%2C%20Culture%3Dneutral%2C%20PublicKeyToken%3Dnull">
<stringID id="ref-3">2ffe7cec-9741-4601-97ab-442840b4bec8-001158a3</stringID>
<intID>1136803</intID>
</a1:SerializableId>
</SOAP-ENV:Body>
</SOAP-ENV:Envelope>

which is about 750 characters on average. That means that roughly for every 700 elements serialized to a dyn file you save something the size of an average novel :D

If we could save just the GUID strings maybe as json, that'd be a reduction of over 90%

* add element binding test to core * re-enabe callsite tests, update files, and load deps manually * add timing test add new test file with 1500 trace elements make traceBinder internal expose protoCore internals to dynamoCoreTests

…#9505) * performance profiling of first load of trace data (#9465) * add element binding test to core * re-enabe callsite tests, update files, and load deps manually * add timing test add new test file with 1500 trace elements make traceBinder internal expose protoCore internals to dynamoCoreTests * modify file versions so they are not from the future

first try

98ba78c

mjkkirschner changed the title ~~first try~~ performance profiling of first load of trace data Jan 31, 2019

aparajit-pratap reviewed Feb 1, 2019

View reviewed changes

src/Engine/ProtoCore/Lang/CallSite.cs Show resolved Hide resolved

add element binding test to core

aaf1c5a

aparajit-pratap reviewed Feb 5, 2019

View reviewed changes

src/Engine/ProtoCore/Lang/CallSite.cs Show resolved Hide resolved

mjkkirschner added 4 commits February 5, 2019 14:52

add todo

667d564

Merge branch 'speedUpBindToType' of https://github.com/mjkkirschner/D…

5f6929f

…ynamo into speedUpBindToType

re-enabe callsite tests, update files, and load deps manually

693b5f6

add timing test

7a85215

add new test file with 1500 trace elements make traceBinder internal expose protoCore internals to dynamoCoreTests

aparajit-pratap reviewed Feb 6, 2019

View reviewed changes

aparajit-pratap added the LGTM Looks good to me label Feb 6, 2019

mjkkirschner merged commit 97e4e20 into DynamoDS:master Feb 6, 2019

mjkkirschner mentioned this pull request Feb 20, 2019

cherry pick performance profiling of first load of trace data (#9465) #9505

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

performance profiling of first load of trace data #9465

performance profiling of first load of trace data #9465

Uh oh!

mjkkirschner commented Jan 31, 2019 •

edited

Loading

Uh oh!

Uh oh!

aparajit-pratap commented Feb 1, 2019

Uh oh!

mjkkirschner commented Feb 4, 2019

Uh oh!

Uh oh!

mjkkirschner commented Feb 6, 2019

Uh oh!

aparajit-pratap Feb 6, 2019 •

edited

Loading

Uh oh!

mjkkirschner Feb 6, 2019 •

edited

Loading

Uh oh!

aparajit-pratap Feb 6, 2019

Uh oh!

aparajit-pratap Feb 6, 2019

Uh oh!

mjkkirschner Feb 6, 2019

Uh oh!

mjkkirschner commented Feb 6, 2019

Uh oh!

dimven commented Feb 8, 2019

Uh oh!

mjkkirschner commented Feb 15, 2019 •

edited

Loading

Uh oh!

dimven commented Feb 15, 2019 •

edited

Loading

Uh oh!

Uh oh!

performance profiling of first load of trace data #9465

performance profiling of first load of trace data #9465

Uh oh!

Conversation

mjkkirschner commented Jan 31, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Purpose

Declarations

Reviewers

FYIs

Uh oh!

Uh oh!

aparajit-pratap commented Feb 1, 2019

Uh oh!

mjkkirschner commented Feb 4, 2019

Uh oh!

Uh oh!

mjkkirschner commented Feb 6, 2019

Uh oh!

aparajit-pratap Feb 6, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mjkkirschner Feb 6, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

aparajit-pratap Feb 6, 2019

Choose a reason for hiding this comment

Uh oh!

aparajit-pratap Feb 6, 2019

Choose a reason for hiding this comment

Uh oh!

mjkkirschner Feb 6, 2019

Choose a reason for hiding this comment

Uh oh!

mjkkirschner commented Feb 6, 2019

Uh oh!

dimven commented Feb 8, 2019

Uh oh!

mjkkirschner commented Feb 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dimven commented Feb 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

mjkkirschner commented Jan 31, 2019 •

edited

Loading

aparajit-pratap Feb 6, 2019 •

edited

Loading

mjkkirschner Feb 6, 2019 •

edited

Loading

mjkkirschner commented Feb 15, 2019 •

edited

Loading

dimven commented Feb 15, 2019 •

edited

Loading