AutoCAD .NET: Huge Delays of ObjectId.Open and Close

The ObjectId.Open and Close look quicker than Transaction. However, one important matter has been ignored. As addressed a bit in some previous posts, the ObjectId.Open approach takes more time than it looks like. After all objects are closed and/or disposed and even the related test command is returned, AutoCAD will still be busy for quite a while and does not respond to any input.

As presented a while back, we created a simple but cool and easy-to-use AutoCAD Performance Meter class, which can help easily measure any operations from three perspectives, code end, command end, and AutoCAD back to response.

In this article, let’s use the gadget to measure the huge delays of the ObjectId.Open and Close calls. Here is the performance meter class again for convenience .

    public class AcadPerformanceMeter
    {
        private System.Diagnostics.Stopwatch mWatch;
        private Autodesk.AutoCAD.EditorInput.Editor mEditor;
        private string mTesterName;

        private double mNominalTotalTime;
        private double mRealTotalTime;
        private double mCodeEndTotalTime = -1;

        public AcadPerformanceMeter(Autodesk.AutoCAD.EditorInput.Editor ed, string testerName)
        {
            mTesterName = testerName;
            mWatch = new Stopwatch();
            mWatch.Start();

            mEditor = ed;
            mEditor.EnteringQuiescentState += EditorEvent_EnteringQuiescentState;
            mEditor.Document.CommandEnded += Document_CommandEnded;
        }

        public void CodeEnd()
        {
            mCodeEndTotalTime = mWatch.Elapsed.TotalMilliseconds;
        }

        private void Document_CommandEnded(object sender, CommandEventArgs e)
        {
            mNominalTotalTime = mWatch.Elapsed.TotalMilliseconds;
            mEditor.Document.CommandEnded -= Document_CommandEnded;
        }

        private void EditorEvent_EnteringQuiescentState(object sender, EventArgs e)
        {
            mWatch.Stop();
            mRealTotalTime = mWatch.Elapsed.TotalMilliseconds;
            mEditor.WriteMessage("{0} in ms. CodeEnd:{1}  CmdEnd:{2}  RealEnd:{3}\n", mTesterName,mCodeEndTotalTime, mNominalTotalTime, mRealTotalTime);
            mEditor.EnteringQuiescentState -= EditorEvent_EnteringQuiescentState;
        }
    }

Here is the test command to meansure both nominal and real performance of the ObjectId.Open and Close calls.

[CommandMethod("RealPerformanceMeterOfObjectIdOpen")]
public static void RealPerformanceMeterOfObjectIdOpen_Method()
{
    Database db = HostApplicationServices.WorkingDatabase;
    try
    {
        AcadPerformanceMeter realTimer = new AcadPerformanceMeter(MgdAcApplication.DocumentManager.MdiActiveDocument.Editor, "Open");
        BlockTableRecord btr = (BlockTableRecord)SymbolUtilityServices.GetBlockModelSpaceId(db).Open(OpenMode.ForRead);
        foreach (ObjectId id in btr)
        {
            Entity ent = (Entity)id.Open(OpenMode.ForWrite);
            ent.ColorIndex = 11;
            ent.Close();
        }
        btr.Close();
        realTimer.CodeEnd();
    }
    catch (System.Exception ex)
    {
        MessageBox.Show(ex.Message);
    }
}

To avoid impact of each other test as much as possible, we kept only one drawing open at a time. Four drawings were used to make the tests and they contained 5000, 15000, 30000, and 60000 entities respectively. Here are the outputs of the series of tests against the four drawings.

Open in ms. CodeEnd:201.1194  CmdEnd:201.9197  RealEnd:343.5888
Open in ms. CodeEnd:361.36  CmdEnd:361.5686  RealEnd:2078.3245
Open in ms. CodeEnd:728.1079  CmdEnd:728.3552  RealEnd:10762.292
Open in ms. CodeEnd:1480.8084  CmdEnd:1481.0427  RealEnd:51016.6387

As can be seen, the code end time is almost the same as the command end time since we don’t do anything else between the code end and the command return. Here is a table that has the code/command end (nominal) performance, real performance, delay and percentage put together.

                 Nominal         Real         Delay     Delay Percentage
5000 Circles       201           343           142         41.40%
15000 Circles      361          2078          1717         82.63%
30000 Circles      728         10762         10034         93.24%
60000 Circles     1481         51017         49537         97.10%

Here is a graph to illustrate the nominal/real performance and the huge delay visually.
 
As can be noticed, the delay becomes longer and longer if more entities need to be processed. Here is the chart to illustrate the trend of the huge delay percentages with object count growing.
 
Why such huge delays for the ObjectId.Open and Close?

Not exactly sure. To make an educational guess here, it looks like the ObjectId.Open and Close do not care about some things like paging, undo filer maintaining, and something like that, but AutoCAD itself does need those to behave normal later, thus it does the cleanup work after the ObjectId.Open and Close calls finish.  More such calls more extra work does AutoCAD have to do, obviously.

Does the Transaction object opening/getting approach have the same delay?

Not at all. We will demonstrate it next. Please stay tuned.

By the way, for readers’ reference, the above tests were performed in AutoCAD 2012 on Windows 7 with duo Intel CORE.

The leading edge AutoCAD .NET Addin Wizard (AcadNetAddinWizard) provides various project wizards, item wizards, coders and widgets to help program AutoCAD .NET addins.

Comments

[Fenton Webb]

Hey Spiderinnet1

I tried on my own sample code, here's the data I got, AutoCAD 2013, 55,000 entities...

Command: STARTTRANSACTION x 3
Open in ms. CodeEnd:764.8677 CmdEnd:767.5765 RealEnd:790.2236
Open in ms. CodeEnd:867.9352 CmdEnd:874.7372 RealEnd:891.2094
Open in ms. CodeEnd:729.969 CmdEnd:737.278 RealEnd:753.6715

Command: OPENCLOSETRANSACTION x 3
Open in ms. CodeEnd:293.4597 CmdEnd:300.9061 RealEnd:656.4242
Open in ms. CodeEnd:291.4521 CmdEnd:298.054 RealEnd:642.7283
Open in ms. CodeEnd:307.2326 CmdEnd:313.6373 RealEnd:731.8031

Command: OpenClose
Open in ms. CodeEnd:334.0489 CmdEnd:336.1482 RealEnd:719.1761
Open in ms. CodeEnd:328.4892 CmdEnd:335.6413 RealEnd:693.8119
Open in ms. CodeEnd:336.7789 CmdEnd:343.9428 RealEnd:702.9882

I think what you are seeing is related to the graphics update/sync that happens at the end of a command. If you are running an unsupported graphics card or maybe you are running software rendering then you'll see bad performance.

[Spiderinnet1]

Fenton, thanks for giving the test a try on your end. In your data, we can still notice the delay of the OpenClose and OpenCloseTransaction, in average, a bit one time more CPU cycles needs to get AutoCAD back to normal after the Open/Close calls end. However, at the same time, we can see the Transaction approach does not have such a huge delay, only with reasonablely a bit more cycles.

I am going to use the same performance meter to measure the Transaction operation in the same drawings opened in the same AutoCAD 2012 running on the same computer having the same graphics card and see what will happen there.

[Spiderinnet1]

Fenton again, please read the latest post about Transaction.GetObject having no delay at all for the same test drawings in the same AutoCAD 2012 running on the same OS with the same hardware configurations including the graphics card.

BTW, your computer is obviously much faster than mine. However, if you try the same code in some bigger size drawings (e.g. having 200,000, 400, 000 and 1M entities), you will see the same trend, I bet, for both the ObjectId.Open and the Transaction.GetObject.