Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

service: Add support for ETW logging #361

Merged
merged 8 commits into from
Aug 25, 2023
Merged

Conversation

bkeryan
Copy link
Collaborator

@bkeryan bkeryan commented Aug 21, 2023

What does this Pull Request accomplish?

Add support for ETW logging using Microsoft's traceloggingdynamic package.

Notes:

  • PerfView is able to correctly calculate elapsed time for these log messages.
  • I wasn't able to get NI's internal ETW viewer to identify these as paired events. I tried specifying event ids, but sometimes the viewer mismatched client/server calls together.
  • This code currently doesn't push/pop the current thread's activity id, so the related activity id is always 0.

Why should this Pull Request be merged?

As a developer, I want better visibility into MeasurementLink measurement execution time

What testing has been done?

Manually tested with PerfView and NI's internal ETW viewer.

Event ids are apparently only for manifest-based logging, not tracelogging.

Activity ids are needed to match up start/stop events.

This enables PerfView to calculate the call duration. ETW Viewer's
event matching doesn't work with this (yet) because it relies on
event id matching.
@bkeryan
Copy link
Collaborator Author

bkeryan commented Aug 21, 2023

Example of PerfView output:
image

@github-actions
Copy link

github-actions bot commented Aug 21, 2023

Test Results

     12 files  ±0       12 suites  ±0   1m 54s ⏱️ -5s
   182 tests ±0     157 ✔️ ±0    25 💤 ±0  0 ±0 
2 172 runs  ±0  1 872 ✔️ ±0  300 💤 ±0  0 ±0 

Results for commit 922d359. ± Comparison against base commit f54b16e.

♻️ This comment has been updated with latest results.

@jasonmreding
Copy link
Collaborator

I wasn't able to get NI's internal ETW viewer to identify these as paired events. I tried specifying event ids, but sometimes the viewer mismatched client/server calls together.

Can multiple start events be emitted before the corresponding stop is emitted? If so, there should be a way to annotate the event as recursive, and you can see if that makes a difference. You can look at the TransactionStart event on the PF event source for an example of this. I'm not sure if a similar concept exists or not in the Python library you're using.

The pairing logic in the viewer has always been a little finicky. I thought there were three different options for trying to pair up event start/stop data. Do none of them work? I guess if the lack of recursive option is causing the events to get dropped, it would probably throw off all of the pairing algorithms.

You could also generate a unique ID that is included with the output of the start/stop event and then use that unique ID to pair start/stop events. That requires hard coding knowledge of that pairing for that event source in ETW Viewer so it's kind of a pain. We could probably generalize the pattern if we find it useful. That might also incur some boxing overhead when logging unless you also provide a matching override of WriteEvent in the event source.

@bkeryan
Copy link
Collaborator Author

bkeryan commented Aug 24, 2023

Run poetry run pytest ./tests -v --cov=ni_measurementlink_service --junitxml=test_results/nims-windows-latest-py3.8.xml
ImportError while loading conftest 'D:\a\measurementlink-python\measurementlink-python\tests\conftest.py'.
tests\conftest.py:9: in <module>
    from ni_measurementlink_service._internal.discovery_client import _get_registration_json_file_path
ni_measurementlink_service\__init__.py:12: in <module>
    from ni_measurementlink_service.measurement.service import (
ni_measurementlink_service\measurement\service.py:30: in <module>
    from ni_measurementlink_service._internal.discovery_client import DiscoveryClient
ni_measurementlink_service\_internal\discovery_client.py:19: in <module>
    from ni_measurementlink_service._loggers import ClientLogger
ni_measurementlink_service\_loggers.py:29: in <module>
    from ni_measurementlink_service import _tracelogging
ni_measurementlink_service\_tracelogging.py:11: in <module>
    _event_provider = traceloggingdynamic.Provider(b"NI-MeasurementLink-Python")
.venv\lib\site-packages\traceloggingdynamic.py:1265: in __init__
    self.id = id if id != None else providerid_from_name_bytes_utf[8](https://github.com/ni/measurementlink-python/actions/runs/5966151523/job/16185221550#step:7:9)(name_utf8)
.venv\lib\site-packages\traceloggingdynamic.py:113: in providerid_from_name_bytes_utf8
    return providerid_from_name(str(providername_utf8, encoding='utf-8'))
.venv\lib\site-packages\traceloggingdynamic.py:[9](https://github.com/ni/measurementlink-python/actions/runs/5966151523/job/16185221550#step:7:10)3: in providerid_from_name
    sha1 = hashlib.sha1(usedforsecurity = False)
E   TypeError: 'usedforsecurity' is an invalid keyword argument for openssl_sha1()
Error: Process completed with exit code 1.

I filed an issue about this: microsoft/tracelogging#58

@bkeryan bkeryan merged commit c189971 into main Aug 25, 2023
17 checks passed
@bkeryan bkeryan deleted the users/bkeryan/etw-logging branch August 25, 2023 21:03
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants