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

pruntime: Structured logging with tracing #1199

Merged
merged 27 commits into from
Mar 24, 2023
Merged

pruntime: Structured logging with tracing #1199

merged 27 commits into from
Mar 24, 2023

Conversation

kvinwang
Copy link
Collaborator

Log lines for concurrent requests are intermixed making it difficult to trace the logic flow. The PR replaces some logs with the tracing crate so that we get structured log lines that can be far easier to understand.
The log looks like this:
image
As you can see there is a line id=114 that is mixed between 119 and 120.

How it works:

  • The crate tracing is designed for structured logging. It can set stacked spans as the scope of each log printing.
  • We use tracing_subscriber::fmt instead of env_logger to init the logger. The tracing_subscriber::fmt is a tracing-subscriber for tracing that prints logs to the console just like env_logger to log. tracing_subscriber::fmt is also a logger for log which bridges the log::* to the tracing framework.
  • We set some tracing instrument points:
    • Each Rocket routes entry point. We assign each request an id so that we can clearly see each log line is printed within which RPC request. (We do this because the Rocket framework itself doesn't support tracing so far. There is a draft PR, but got inactive for a long time)
    • The dylib pink runtime entry point. To pass the request id to the tracing framework inside.
    • The dylib pink runtime ocalls point.
    • The sidevm instance serving entry point.

@kvinwang kvinwang changed the title Structured logging with tracing pruntime: Structured logging with tracing Mar 15, 2023
@h4x3rotab
Copy link
Contributor

Very useful and looks promising

Copy link
Contributor

@h4x3rotab h4x3rotab left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice. Also simplified a lot of logging code.

crates/phactory/src/benchmark.rs Show resolved Hide resolved
standalone/pruntime/src/main.rs Outdated Show resolved Hide resolved
@@ -17,6 +17,7 @@ LD_LIBRARY_PATH = "/lib:/lib/x86_64-linux-gnu"
MALLOC_ARENA_MAX = "1"
ROCKET_WORKERS = "8"
PINK_RUNTIME_PATH = "{{ pink_runtime_mount_dir }}"
RUST_LOG_SANITIZED = "true"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How about document it somewhere?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Didn't find a good place elsewhere. Let me just add some comments to this file.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe we can create a simple doc file for pruntime startup flags.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

crates/phala-sanitized-logger/src/subscriber.rs Outdated Show resolved Hide resolved
@kvinwang kvinwang requested a review from h4x3rotab March 17, 2023 01:59
Base automatically changed from metrics to master March 24, 2023 15:09
@kvinwang kvinwang merged commit be7e308 into master Mar 24, 2023
@kvinwang kvinwang deleted the tracing branch March 24, 2023 15:40
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.

2 participants