microsoft / microsoft/perfview
GetILOffsetForNativeAddress decrementing returned IL offset leads to wrongly-attributed samples
Nobody has claimed this yet.
- Dominant language
- C#
- Stars
- 4.7k
- Forks
- 775
- Avg merge
- 5d 11h
- Merged PRs (30d)
- 9
Description
We are working on adding sample-based PGO support to .NET Core. As part of this, I am using TraceEvent to parse traces and retrieve the samples as a (method, IL offset) pair. We are seeing some strange samples because of the following:
https://github.com/microsoft/perfview/blob/3d2809c029715ad5104c0b25f0083283f1626e7f/src/TraceEvent/TraceLog.cs#L9184-L9190
I am not quite sure what the comment is describing, but it definitely leads to wrongly attributed samples. For example, in
https://github.com/dotnet/performance/blob/b195acece4d20efc00a9e36bed854d6cf41ddaa6/src/benchmarks/micro/runtime/BenchmarksGame/k-nucleotide-9.cs#L184-L206
the loop calling checkEnding is very hot. The raw IP samples we see are the following:
https://gist.github.com/jakobbotsch/bda616056b6859e551d606df41e1fb6d#file-count_ending-asm-L105-L130
which all look very reasonable. However, for the 101 samples on
00007ff8`21166da9 4C8B4D18 mov r9, qword ptr [rbp+18H] ; 101
TraceCodeAddresses.ILOffset is returning 0x37, which is the middle of the previous instruction that is not part of the loop:
.method private hidebysig static class [System.Collections]System.Collections.Generic.Dictionary`2<int64, class BenchmarksGame.Wrapper>
countEnding(
int32 l,
int64 mask,
unsigned int8 b
) cil managed
{
.maxstack 5
.locals init (
[0] int64 rollingKey,
[1] unsigned int8[] firstBlock,
[2] int32 start,
[3] class [System.Collections]System.Collections.Generic.Dictionary`2<int64, class BenchmarksGame.Wrapper> dict,
[4] int32 lastBlockId,
[5] unsigned int8[] lastBlock,
[6] int32 i,
[7] int32 bl,
[8] unsigned int8[] bytes,
[9] int32 i_V_9,
[10] int32 i_V_10
)
// [186 13 - 186 33]
IL_0000: ldc.i4.0
IL_0001: conv.i8
IL_0002: stloc.0 // rollingKey
// [187 13 - 187 45]
IL_0003: ldsfld class [System.Collections]System.Collections.Generic.List`1<unsigned int8[]> BenchmarksGame.KNucleotide_9::threeBlocks
IL_0008: ldc.i4.0
IL_0009: callvirt instance !0/*unsigned int8[]*/ class [System.Collections]System.Collections.Generic.List`1<unsigned int8[]>::get_Item(int32)
IL_000e: stloc.1 // firstBlock
// [188 13 - 188 36]
IL_000f: ldsfld int32 BenchmarksGame.KNucleotide_9::threeStart
IL_0014: stloc.2 // start
IL_0015: br.s IL_0024
// start of loop, entry point: IL_0024
// [189 29 - 189 82]
IL_0017: ldloc.0 // rollingKey
IL_0018: ldc.i4.2
IL_0019: shl
IL_001a: ldloc.1 // firstBlock
IL_001b: ldloc.2 // start
IL_001c: dup
IL_001d: ldc.i4.1
IL_001e: add
IL_001f: stloc.2 // start
IL_0020: ldelem.u1
IL_0021: conv.u8
IL_0022: or
IL_0023: stloc.0 // rollingKey
// [189 13 - 189 28]
IL_0024: ldarg.0 // l
IL_0025: ldc.i4.1
IL_0026: sub
IL_0027: dup
IL_0028: starg.s l
IL_002a: ldc.i4.0
IL_002b: bgt.s IL_0017
// end of loop
// [190 13 - 190 56]
IL_002d: newobj instance void class [System.Collections]System.Collections.Generic.Dictionary`2<int64, class BenchmarksGame.Wrapper>::.ctor()
IL_0032: stloc.3 // dict
// [191 18 - 191 31]
IL_0033: ldloc.2 // start
IL_0034: stloc.s i
IL_0036: br.s IL_004c
// start of loop, entry point: IL_004c
// [192 17 - 192 75]
IL_0038: ldloc.3 // dict
IL_0039: ldloca.s rollingKey
IL_003b: ldarg.2 // b
IL_003c: ldloc.1 // firstBlock
IL_003d: ldloc.s i
IL_003f: ldelem.u1
IL_0040: ldarg.1 // mask
IL_0041: call void BenchmarksGame.KNucleotide_9::checkEnding(class [System.Collections]System.Collections.Generic.Dictionary`2<int64, class BenchmarksGame.Wrapper>, int64&, unsigned int8, unsigned int8, int64)
// [191 56 - 191 59]
IL_0046: ldloc.s i
IL_0048: ldc.i4.1
IL_0049: add
IL_004a: stloc.s i
// [191 33 - 191 54]
IL_004c: ldloc.s i
IL_004e: ldloc.1 // firstBlock
IL_004f: ldlen
IL_0050: conv.i4
IL_0051: blt.s IL_0038
// end of loop
// [194 13 - 194 53]
IL_0053: ldsfld class [System.Collections]System.Collections.Generic.List`1<unsigned int8[]> BenchmarksGame.KNucleotide_9::threeBlocks
IL_0058: callvirt instance int32 class [System.Collections]System.Collections.Generic.List`1<unsigned int8[]>::get_Count()
IL_005d: ldc.i4.1
IL_005e: sub
IL_005f: stloc.s lastBlockId
// [195 18 - 195 28]
IL_0061: ldc.i4.1
IL_0062: stloc.s bl
IL_0064: br.s IL_009c
// start of loop, entry point: IL_009c
// [197 17 - 197 45]
IL_0066: ldsfld class [System.Collections]System.Collections.Generic.List`1<unsigned int8[]> BenchmarksGame.KNucleotide_9::threeBlocks
IL_006b: ldloc.s bl
IL_006d: callvirt instance !0/*unsigned int8[]*/ class [System.Collections]System.Collections.Generic.List`1<unsigned int8[]>::get_Item(int32)
IL_0072: stloc.s bytes
// [198 22 - 198 31]
IL_0074: ldc.i4.0
IL_0075: stloc.s i_V_9
IL_0077: br.s IL_008e
// start of loop, entry point: IL_008e
// [199 21 - 199 74]
IL_0079: ldloc.3 // dict
IL_007a: ldloca.s rollingKey
IL_007c: ldarg.2 // b
IL_007d: ldloc.s bytes
IL_007f: ldloc.s i_V_9
IL_0081: ldelem.u1
IL_0082: ldarg.1 // mask
IL_0083: call void BenchmarksGame.KNucleotide_9::checkEnding(class [System.Collections]System.Collections.Generic.Dictionary`2<int64, class BenchmarksGame.Wrapper>, int64&, unsigned int8, unsigned int8, int64)
// [198 51 - 198 54]
IL_0088: ldloc.s i_V_9
IL_008a: ldc.i4.1
IL_008b: add
IL_008c: stloc.s i_V_9
// [198 33 - 198 49]
IL_008e: ldloc.s i_V_9
IL_0090: ldloc.s bytes
IL_0092: ldlen
IL_0093: conv.i4
IL_0094: blt.s IL_0079
// end of loop
// [195 48 - 195 52]
IL_0096: ldloc.s bl
IL_0098: ldc.i4.1
IL_0099: add
IL_009a: stloc.s bl
// [195 30 - 195 46]
IL_009c: ldloc.s bl
IL_009e: ldloc.s lastBlockId
IL_00a0: blt.s IL_0066
// end of loop
// [202 13 - 202 54]
IL_00a2: ldsfld class [System.Collections]System.Collections.Generic.List`1<unsigned int8[]> BenchmarksGame.KNucleotide_9::threeBlocks
IL_00a7: ldloc.s lastBlockId
IL_00a9: callvirt instance !0/*unsigned int8[]*/ class [System.Collections]System.Collections.Generic.List`1<unsigned int8[]>::get_Item(int32)
IL_00ae: stloc.s lastBlock
// [203 18 - 203 27]
IL_00b0: ldc.i4.0
IL_00b1: stloc.s i_V_10
IL_00b3: br.s IL_00ca
// start of loop, entry point: IL_00ca
// [204 17 - 204 74]
IL_00b5: ldloc.3 // dict
IL_00b6: ldloca.s rollingKey
IL_00b8: ldarg.2 // b
IL_00b9: ldloc.s lastBlock
IL_00bb: ldloc.s i_V_10
IL_00bd: ldelem.u1
IL_00be: ldarg.1 // mask
IL_00bf: call void BenchmarksGame.KNucleotide_9::checkEnding(class [System.Collections]System.Collections.Generic.Dictionary`2<int64, class BenchmarksGame.Wrapper>, int64&, unsigned int8, unsigned int8, int64)
// [203 43 - 203 46]
IL_00c4: ldloc.s i_V_10
IL_00c6: ldc.i4.1
IL_00c7: add
IL_00c8: stloc.s i_V_10
// [203 29 - 203 41]
IL_00ca: ldloc.s i_V_10
IL_00cc: ldsfld int32 BenchmarksGame.KNucleotide_9::threeEnd
IL_00d1: blt.s IL_00b5
// end of loop
// [205 13 - 205 25]
IL_00d3: ldloc.3 // dict
IL_00d4: ret
} // end of method KNucleotide_9::countEnding
Logically, the IL offset 0x37 is part of the basic block that allocates the dictionary. For now I am working around this by adding 1 to the IL offsets returned by TraceEvent, but a more central fix would be nice.
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start in src/TraceEvent/TraceLog.cs at the GetILOffsetForNativeAddress logic linked in the issue, and inspect how TraceCodeAddresses.ILOffset is derived from native sample addresses. Reproduce the reported countEnding samples using the linked trace data, then verify that returned offsets identify the sampled instruction rather than the preceding basic block.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- csharp
- Domain
- performance
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100