Re: Network Stack Budgeting

["Tomas Pilar (tpilar)" <tpilar@solarflare.com>]

Hi Laszlo,

> Can you capture a call stack when Snp.Start() is invoked for the very
> first time (which, IIUC, is a call that should not happen, in your
> opinion)?
>
Unfortunately I do not have access to the platform firmware itself (I maintain an IHV network driver that's shipped in OptionROMs) and I don't believe a generic stack capture is available in EDK2 yet. However I have comprehensive debug from my driver that shows that our driver gets a DriverBinding.Start() at TPL_APPLICATION and we perform the entire probe at TPL_NOTIFY and as soon as that completes and we drop the TPL, the newly installed SNP gets a Snp.Start() call at TPL_CALLBACK - I assume that MNP or something higher had an event registered that fired as soon as the TPL dropped after the DriverBinding.Start() finished.

Here is a snip of the debug log (that I assume will not be of much interest). We don't observe the actual call to DriverBinding.Start() because the debug output is initialised as one of the first things that method does.


      1 [sfc]..|INFO: [sfc] Debug  Output Initialised
      2 [sfc]..|INFO: Linked list max_size=1000000
      3 [sfc]..|SfcDebugLibStart:208 [Not Found]
      4 [sfc]..|[0x866D9396<] SfcDebugLibStart:222 [Success]
      5 [sfc]..|INFO: Running Solarflare UEFI Driver 2.7.8.5 (f71064c4d0a0) for MEDFORD
      6 [sfc]..|INFO: Ctrl=954E4B18 Driver=954E4418 Image=866B0000 Size=0x4D9C0 loaded from Device=954E4B18
      7 [sfc]..|INFO: Probing PciDev=942C3118
... snip ...
    376 [sfc]..|INFO: Support strings done
    377 [sfc]..|INFO: Hii init on hunt=942A6018 complete
    378 [sfc]..|TRACE: Closing the DeferredInit event
    379 [sfc]..|INFO: Processed deferred init okay
    380 [sfc].|[0x9940F873<] GetSupportedTypes:178 [Success]
    381 [sfc]|[0x9D4E1DE8<] DriverBindingStart:211 [Success]
    382 [sfc].|INFO: Starting SNP=942A2018
    383 [sfc].|[0x99653BA4<] SimpleNetworkStart:33 [Success]
    384 [sfc].|INFO: Init snp=942A2018
    385 [sfc].|TRACE: INIT: Found netdev=942A5D18
    386 [sfc].|INFO: Hunt open netdev=942A5D18
    387 [sfc].|INFO: Resetting mcdi=942A6480
    388 [sfc].|[Base+0x209E0<] HuntReset:312 [Success]
    389 [sfc].|INFO: Allocating vis count=3 on mcdi=942A6480
... snip ...
    491 [sfc].|TRACE: Final state filters=0x942A2018 mcastcnt=7
    492 [sfc].|TRACE: Filter Snp=942A2018 Add=0x7 Del=0x18 Reset=0 McastCount=1 List=9400EE98
    493 [sfc].|TRACE: Final state filters=0x942A2018 mcastcnt=7
    494 [sfc].|TRACE: Filter Snp=942A2018 Add=0x7 Del=0x18 Reset=0 McastCount=2 List=93FB5A98
    495 [sfc].|TRACE: Final state filters=0x942A2018 mcastcnt=7
    496 [sfc]|TRACE: Name Handle=0x954E4B18 PciDev=942C3118 Child=0x0
    497 [sfc]|INFO: STR [*ControllerName]=[Solarflare Adapter 17:00.0]
    498 [sfc]|TRACE: Name Handle=0x954E4B18 PciDev=942C3118 Child=0x942A5F98
    499 [sfc]|INFO: STR [*ControllerName]=[Solarflare NIC [00:0F:53:4C:A7:A0]]
    500 [sfc]..|INFO: [sfc] Debug  Output Initialised
    501 [sfc]..|INFO: Linked list max_size=1000000
    502 [sfc]..|SfcDebugLibStart:208 [Not Found]
    503 [sfc]..|[Base+0x29396<] SfcDebugLibStart:222 [Success]
    504 [sfc]..|INFO: Running Solarflare UEFI Driver 2.7.8.5 (f71064c4d0a0) for MEDFORD
    505 [sfc]..|INFO: Ctrl=954E3B98 Driver=954E4418 Image=866B0000 Size=0x4D9C0 loaded from Device=954E4B18
... snip ...
---

The dots between [sfc] and | symbol indicate the TPL the operation is being carried out at. No dots mean TPL_APPLICATION, one dot is TPL_CALLBACK etc. You can see that the Snp.Start() on the first device is called before even the second device gets a DriverBinding.Start().

Cheers,
Tom