microsoft / microsoft/perfview

GetILOffsetForNativeAddress decrementing returned IL offset leads to wrongly-attributed samples

Open
#1,410 0 comments 0 reactions 0 assignees View on GitHub

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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.