Add timing information for methods

[hfickes]

Would it be possible to add timing information for each method in the users code?

Not asking for each line, that would be too much, but since the instrumentation intercepts each call, how hard would it be to add a timing option as well?

Thanks,
Herb

[SteveGilham]

This is implicitly available through the callContext option, which does record every visit as instrumented -

  -c, --callContext=VALUE    Optional, multiple: Tracking either times of
                               visits in ticks or designated method calls
                               leading to the visits.
                                   A single digit 0-7 gives the number of
                               decimal places of seconds to report; everything
                               else is at the mercy of the system clock
                               information available through DateTime.UtcNow
...

The times are just recorded as-is; any post-processing would be for the end-user to define.
Combined with --methodpoint would cut down the recording to the entry to each method; method exits are not specially handled - that requires rather more flow analysis, especially in the case of exceptions, than simply adding an "I was here" call at each sequence point.

[SteveGilham]

Correcting myself slightly (after reminding myself how code that I wrote 5 years ago works in detail) -

1. specific tracked methods by name or by attribute are instrumented to capture entry and exit, to know when the context is complete, by means of wrapping a try/finally around those methods to track context state, and will record entry and exit times if timing information has been requested
2. the feature doesn't work with --methodpoint because it would conflict with the above, at least as currently implemented.

[hfickes]

I haven't been able to find any timing information when using the --callContext option, probably because I'm doing it wrong?

--callContext=2 to get two decimal places worth information (more than needed really)

I'm looking in the resulting openCover style xml and haven't seen anything timing related.

However the documentation seems to suggest that I need to put method names here as well?

From https://stevegilham.github.io/altcover/AltCover.PowerShell/AltCover.Commands/InvokeAltCoverCommand/CallContext-apidoc.html

"Tracking either times of visits in ticks or designated method calls leading to the visits.

A single digit 0-7 gives the number of decimal places of seconds to report; everything else is at the mercy of the system clock information available through DateTime.UtcNow

A string in brackets “[]” is interpreted as an attribute type name (the trailing “Attribute” is optional), so [Test] or [TestAttribute] will match; if the name contains one or more “.”, then it will be matched against the full name of the attribute type.

Other strings are interpreted as method names (fully qualified if the string contains any “.” characters)."

Thanks for the help

[hfickes]

I've tried it both with a -c and without the -c switch and I can't tell where the timing is within the xml when the -c is used.

altcover.exe -c -s=Scrpt.Tests -s=nunit.framework -s=NUnit3.TestAdapter --sn=c:\projects\scrpt\scrptKey.snk -- "c:\Program files (x86)\NUnit.org\nunit-console\nunit3-console.exe" scrpt.tests.dll --stoponerror

The output is the opencover format and I use nunit3 as the test runner for this .Net framework 4.8 project.

Any ideas of what I'm doing wrong?

[SteveGilham]

Looks like three problems in that example

1. the tests appear to be run against the uninstrumented assembly : it would need either

altcover.exe -c -s=Scrpt.Tests -s=nunit.framework -s=NUnit3.TestAdapter --sn=c:\projects\scrpt\scrptKey.snk -- "c:\Program files (x86)\NUnit.org\nunit-console\nunit3-console.exe" __Instrumented\scrpt.tests.dll --stoponerror

to point the unit tests at the defaulted location of the instrumented assembly, or the inplace flag

altcover.exe -c -s=Scrpt.Tests -s=nunit.framework -s=NUnit3.TestAdapter --sn=c:\projects\scrpt\scrptKey.snk --inplace -- "c:\Program files (x86)\NUnit.org\nunit-console\nunit3-console.exe" scrpt.tests.dll --stoponerror

to copy out and then instrument back

2. No value supplied to the -c flag at least in that quoted fragment; it will be consuming the next argument as a method name. Supplying a numeric value (3 arbitrarily chosen here) will trigger timing information collection

altcover.exe -c=3 -s=Scrpt.Tests -s=nunit.framework -s=NUnit3.TestAdapter --sn=c:\projects\scrpt\scrptKey.snk -- "c:\Program files (x86)\NUnit.org\nunit-console\nunit3-console.exe" __Instrumented\scrpt.tests.dll --stoponerror

3. the use of "classic" (NCover 1.5.8 style) mode. Because process exit handlers only have a short permitted duration, this generates a minimal report - just the raw visit counts - is generated. While allowing significantly sized systems to gather coverage data sufficient for build status reporting (e.g. via coveralls, ReportGenerator, ...) , this comes at the cost of all the bells and whistles.

Timing information (along with summary data and other derived quantities) is handled in the post-processing part of the collect ("runner") stage. That would finally be something like

altcover.exe -c=3 -s=Scrpt.Tests -s=nunit.framework -s=NUnit3.TestAdapter --sn=c:\projects\scrpt\scrptKey.snk --save -- "c:\Program files (x86)\NUnit.org\nunit-console\nunit3-console.exe" __Instrumented\scrpt.tests.dll --stoponerror
altcover.exe runner --collect -r __Instrumented

to fill in the XML report, which should then contain data like

            <Method visited="true" cyclomaticComplexity="1" nPathComplexity="0" sequenceCoverage="100" branchCoverage="0" isConstructor="false" isStatic="true" isGetter="false" isSetter="false" crapScore="1">
              <Summary numSequencePoints="1" visitedSequencePoints="1" numBranchPoints="1" visitedBranchPoints="0" sequenceCoverage="100" branchCoverage="0" maxCyclomaticComplexity="1" minCyclomaticComplexity="1" visitedClasses="0" numClasses="0" visitedMethods="1" numMethods="1" minCrapScore="1" maxCrapScore="1" />
              <MetadataToken>100663362</MetadataToken>
              <Name>AltCover.PointVisit AltCover.PointVisit::Create()</Name>
              <FileRef uid="2" />
              <SequencePoints>
                <SequencePoint vc="49" uspid="2" ordinal="0" offset="0" sl="68" sc="37" el="68" ec="75" bec="0" bev="0" fileid="2">
                  <Times>
                    <Time time="638192380986820000" vc="1" />
                    <Time time="638192380986830000" vc="1" />
                    <Time time="638192380986840000" vc="1" />
                    <Time time="638192380988680000" vc="1" />
...

[hfickes]

Thank you. Items 2 and 3 were what I was missing.

This is providing an enormous amount of data for us. Thank you very much both for the testing tool and your help here as well.

[SteveGilham]

My pleasure. Glad to be of service.