[iOS tracing] Inject iOS system log events into perfetto traces [chromium/src : main]
Etienne Pierre-Doray (Gerrit)
Etienne Pierre-Doray added 3 comments![]( "Open in Gerrit")
// We have no way to know whether other data sources have already added
// a track and thread descriptor for this thread, so we add one just in
// case. Perfetto's incremental state tracking handles deduplication
// automatically.
if (seen_threads.insert(thread_id).second) {
auto packet = ctx.NewTracePacket();
auto* track_descriptor = packet->set_track_descriptor();
track_descriptor->set_uuid(thread_track_uuid);
track_descriptor->set_parent_uuid(thread_track.parent_uuid);
auto* thread = track_descriptor->set_thread();
thread->set_pid(thread_track.pid);
thread->set_tid(thread_id);
const char* thread_name =
base::ThreadIdNameManager::GetInstance()->GetName(
base::PlatformThreadId(thread_id));
if (thread_name && thread_name[0] != '\0') {
thread->set_thread_name(thread_name);
} else {
// Fallback: if this thread is not known to Chromium, we must still
// provide a thread descriptor with some name for it.
thread->set_thread_name("Unknown Thread");
}
}
I find this awkward - emitting track event data is a lot of boilerplate when not using TRACE_EVENT macros directly.
I hit a similar problem for SystemMetricsSampler:
https://source.chromium.org/chromium/chromium/src/+/main:services/tracing/public/cpp/system_metrics_sampler.cc?q=systemmetricssampler&ss=chromium
I ended up using a combination of DataSource (to allow configuration and capturing Start/Stop) + using TRACE_EVENT directly, which is a bit weird (because it requires enabling both the category and the data source, which is the case here as well) but a lot simpler.
This could also be a simple TRACE_EVENT + TraceSessionObserver if you don't need a dedicated DataSourceConfig and state.
track_event->add_categories("os_log");Let's have this match the category in AddDataSourceConfigs()
TRACE_DISABLED_BY_DEFAULT("os_log"))) {Let's add the category in base/trace_event/builtin_categories.h
Nit: TRACE_DISABLED_BY_DEFAULT is mostly deprecated, I'd recommend seomthing like "ios.log.debug"
Related details
- Justin Cohen
- Justin Novosad
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad added 3 comments![]( "Open in Gerrit")
// We have no way to know whether other data sources have already added
// a track and thread descriptor for this thread, so we add one just in
// case. Perfetto's incremental state tracking handles deduplication
// automatically.
if (seen_threads.insert(thread_id).second) {
auto packet = ctx.NewTracePacket();
auto* track_descriptor = packet->set_track_descriptor();
track_descriptor->set_uuid(thread_track_uuid);
track_descriptor->set_parent_uuid(thread_track.parent_uuid);
auto* thread = track_descriptor->set_thread();
thread->set_pid(thread_track.pid);
thread->set_tid(thread_id);
const char* thread_name =
base::ThreadIdNameManager::GetInstance()->GetName(
base::PlatformThreadId(thread_id));
if (thread_name && thread_name[0] != '\0') {
thread->set_thread_name(thread_name);
} else {
// Fallback: if this thread is not known to Chromium, we must still
// provide a thread descriptor with some name for it.
thread->set_thread_name("Unknown Thread");
}
}
I find this awkward - emitting track event data is a lot of boilerplate when not using TRACE_EVENT macros directly.
I hit a similar problem for SystemMetricsSampler:
https://source.chromium.org/chromium/chromium/src/+/main:services/tracing/public/cpp/system_metrics_sampler.cc?q=systemmetricssampler&ss=chromiumI ended up using a combination of DataSource (to allow configuration and capturing Start/Stop) + using TRACE_EVENT directly, which is a bit weird (because it requires enabling both the category and the data source, which is the case here as well) but a lot simpler.
This could also be a simple TRACE_EVENT + TraceSessionObserver if you don't need a dedicated DataSourceConfig and state.
Oh, wow. It's so much simpler that way. Thanks!
Done.
Let's have this match the category in AddDataSourceConfigs()
Done
Let's add the category in base/trace_event/builtin_categories.h
Nit: TRACE_DISABLED_BY_DEFAULT is mostly deprecated, I'd recommend seomthing like "ios.log.debug"
- Etienne Pierre-Doray
- Justin Cohen
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Etienne Pierre-Doray (Gerrit)
Etienne Pierre-Doray added 3 comments![]( "Open in Gerrit")
session_->FlushBlocking();I'd expect this to happen already as part of StopBlocking below.
auto thread_track = perfetto::ThreadTrack::ForThread(thread_id);Nit: You might want to create a named track scoped by the ThreadTrack, e.g.
`NamedTrack("OSLog", 0, thread_track)` if you want this to appear separately from the regular thread's trace events.
inline constexpr char kOsLogSourceName[] = "org.chromium.os_log";I think the data source name should have ios in the name as well?
Related details
- Justin Cohen
- Justin Novosad
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad added 3 comments![]( "Open in Gerrit")
session_->FlushBlocking();I'd expect this to happen already as part of StopBlocking below.
This call became necessary after your recommendation of using TRACE_EVENT_INSTANT directly inside `OSLogDataSource::ExtractAndTrace`. Without this flush, trace recording is stopped before the final call to `OSLogDataSource::ExtractAndTrace`, which causes the TRACE_EVENT_INSTANT invocations inside `OSLogDataSource::ExtractAndTrace` to be no-ops.
auto thread_track = perfetto::ThreadTrack::ForThread(thread_id);Nit: You might want to create a named track scoped by the ThreadTrack, e.g.
`NamedTrack("OSLog", 0, thread_track)` if you want this to appear separately from the regular thread's trace events.
I tried it just to see but ended up reverting. The traces are easier to interpret this way.
inline constexpr char kOsLogSourceName[] = "org.chromium.os_log";I think the data source name should have ios in the name as well?
- Etienne Pierre-Doray
- Justin Cohen
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad voted and added 1 comment![]( "Open in Gerrit")
Votes added by Justin Novosad
| Commit-Queue | +1 |
1 comment
session_->FlushBlocking();Justin NovosadI'd expect this to happen already as part of StopBlocking below.
This call became necessary after your recommendation of using TRACE_EVENT_INSTANT directly inside `OSLogDataSource::ExtractAndTrace`. Without this flush, trace recording is stopped before the final call to `OSLogDataSource::ExtractAndTrace`, which causes the TRACE_EVENT_INSTANT invocations inside `OSLogDataSource::ExtractAndTrace` to be no-ops.
Hmmm... This seems to be causing a "NOTREACHED" crash on other platforms, in `ConsumerEndpoint::Flush`. I need to figure this out....
Related details
- Etienne Pierre-Doray
- Justin Cohen
- Justin Novosad
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad added 1 comment![]( "Open in Gerrit")
session_->FlushBlocking();Justin NovosadI'd expect this to happen already as part of StopBlocking below.
Justin NovosadThis call became necessary after your recommendation of using TRACE_EVENT_INSTANT directly inside `OSLogDataSource::ExtractAndTrace`. Without this flush, trace recording is stopped before the final call to `OSLogDataSource::ExtractAndTrace`, which causes the TRACE_EVENT_INSTANT invocations inside `OSLogDataSource::ExtractAndTrace` to be no-ops.
Hmmm... This seems to be causing a "NOTREACHED" crash on other platforms, in `ConsumerEndpoint::Flush`. I need to figure this out....
- Etienne Pierre-Doray
- Justin Cohen
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Etienne Pierre-Doray (Gerrit)
Etienne Pierre-Doray added 1 comment![]( "Open in Gerrit")
session_->FlushBlocking();Justin NovosadI'd expect this to happen already as part of StopBlocking below.
Justin NovosadThis call became necessary after your recommendation of using TRACE_EVENT_INSTANT directly inside `OSLogDataSource::ExtractAndTrace`. Without this flush, trace recording is stopped before the final call to `OSLogDataSource::ExtractAndTrace`, which causes the TRACE_EVENT_INSTANT invocations inside `OSLogDataSource::ExtractAndTrace` to be no-ops.
Justin NovosadHmmm... This seems to be causing a "NOTREACHED" crash on other platforms, in `ConsumerEndpoint::Flush`. I need to figure this out....
Fixed.
I see, I think this is because perfetto doesn't support emitting track event data during tear down of another data source (or rather it doesn't guarantee that such data would flush correctly).
This suggests it isn't guaranteed to work in production either, so I don't think this is a suitable work around 😞
I see 2 alternatives:
1- Go back to the original impl of emitting direct track event protos (with all the boiler plate)
2- Use TraceSessionObserver (much simpler), which hooks directly in the TrackEventDataSource. The downside is that you wouldn't be able to define a custom config, but you're not using one currently. TraceSessionObserver is currently missing OnFlush(), but I sent a perfetto pull request to fix that: https://github.com/google/perfetto/pull/6033
This is only needed when taking snapshots, so it'd be mostly fine to do only OnStop() for now.
Related details
- Justin Cohen
- Justin Novosad
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad added 1 comment![]( "Open in Gerrit")
session_->FlushBlocking();Justin NovosadI'd expect this to happen already as part of StopBlocking below.
Justin NovosadThis call became necessary after your recommendation of using TRACE_EVENT_INSTANT directly inside `OSLogDataSource::ExtractAndTrace`. Without this flush, trace recording is stopped before the final call to `OSLogDataSource::ExtractAndTrace`, which causes the TRACE_EVENT_INSTANT invocations inside `OSLogDataSource::ExtractAndTrace` to be no-ops.
Justin NovosadHmmm... This seems to be causing a "NOTREACHED" crash on other platforms, in `ConsumerEndpoint::Flush`. I need to figure this out....
Etienne Pierre-DorayFixed.
I see, I think this is because perfetto doesn't support emitting track event data during tear down of another data source (or rather it doesn't guarantee that such data would flush correctly).
This suggests it isn't guaranteed to work in production either, so I don't think this is a suitable work around 😞I see 2 alternatives:
1- Go back to the original impl of emitting direct track event protos (with all the boiler plate)
2- Use TraceSessionObserver (much simpler), which hooks directly in the TrackEventDataSource. The downside is that you wouldn't be able to define a custom config, but you're not using one currently. TraceSessionObserver is currently missing OnFlush(), but I sent a perfetto pull request to fix that: https://github.com/google/perfetto/pull/6033
This is only needed when taking snapshots, so it'd be mostly fine to do only OnStop() for now.
Okay, I did #2. It's just missing the OnFlush implementation, which I'll add once your perfetto PR lands.
Related details
- Etienne Pierre-Doray
- Justin Cohen
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad added 1 comment![]( "Open in Gerrit")
@etiennep : This is really annoying: There is a crash on the bots that I am unable to repro locally. For some reason `perfetto::Track::MakeThreadTrack` is sometimes receiving a thread id of 0 (invalid). Have you ever seen anything like this?
Related details
- Etienne Pierre-Doray
- Justin Cohen
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Etienne Pierre-Doray (Gerrit)
Etienne Pierre-Doray added 1 comment![]( "Open in Gerrit")
@etiennep : This is really annoying: There is a crash on the bots that I am unable to repro locally. For some reason `perfetto::Track::MakeThreadTrack` is sometimes receiving a thread id of 0 (invalid). Have you ever seen anything like this?
There is a crash on the bots that I am unable to repro locally.
I can't find it from the CQ, do you have a link?
ThreadTrack get its thread_id from perfetto::Platform:: GetCurrentThreadId(), which is overridden by PerfettoPlatform::GetCurrentThreadId().
Though in test it might be using the default perfetto::base::GetThreadId().
In both cases, this does pthread_threadid_np(nullptr, &tid), although the PlatformThreadBase::CurrentId CHECKs for error.
Related details
- Justin Cohen
- Justin Novosad
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad added 1 comment![]( "Open in Gerrit")
Etienne Pierre-Doray@etiennep : This is really annoying: There is a crash on the bots that I am unable to repro locally. For some reason `perfetto::Track::MakeThreadTrack` is sometimes receiving a thread id of 0 (invalid). Have you ever seen anything like this?
There is a crash on the bots that I am unable to repro locally.
I can't find it from the CQ, do you have a link?
ThreadTrack get its thread_id from perfetto::Platform:: GetCurrentThreadId(), which is overridden by PerfettoPlatform::GetCurrentThreadId().
Though in test it might be using the default perfetto::base::GetThreadId().In both cases, this does pthread_threadid_np(nullptr, &tid), although the PlatformThreadBase::CurrentId CHECKs for error.
Oh yeah, looks like my speculative fix in Patchset 15 solved the crash. It lookls like the thread ID = 0 was coming from the thread ID field of system log events. That's weird, but not a big deal. I just created a new NamedTrack for stick all the log entries that don't have thread IDs.
Now the main issue is that one of the test became flaky due to a duplicated log entry. That's a completely separate issue.
Related details
- Etienne Pierre-Doray
- Justin Cohen
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad added 1 comment![]( "Open in Gerrit")
session_->FlushBlocking();Justin NovosadI'd expect this to happen already as part of StopBlocking below.
Justin NovosadThis call became necessary after your recommendation of using TRACE_EVENT_INSTANT directly inside `OSLogDataSource::ExtractAndTrace`. Without this flush, trace recording is stopped before the final call to `OSLogDataSource::ExtractAndTrace`, which causes the TRACE_EVENT_INSTANT invocations inside `OSLogDataSource::ExtractAndTrace` to be no-ops.
Justin NovosadHmmm... This seems to be causing a "NOTREACHED" crash on other platforms, in `ConsumerEndpoint::Flush`. I need to figure this out....
Etienne Pierre-DorayFixed.
Justin NovosadI see, I think this is because perfetto doesn't support emitting track event data during tear down of another data source (or rather it doesn't guarantee that such data would flush correctly).
This suggests it isn't guaranteed to work in production either, so I don't think this is a suitable work around 😞I see 2 alternatives:
1- Go back to the original impl of emitting direct track event protos (with all the boiler plate)
2- Use TraceSessionObserver (much simpler), which hooks directly in the TrackEventDataSource. The downside is that you wouldn't be able to define a custom config, but you're not using one currently. TraceSessionObserver is currently missing OnFlush(), but I sent a perfetto pull request to fix that: https://github.com/google/perfetto/pull/6033
This is only needed when taking snapshots, so it'd be mostly fine to do only OnStop() for now.
Okay, I did #2. It's just missing the OnFlush implementation, which I'll add once your perfetto PR lands.
Done
Related details
- Etienne Pierre-Doray
- Justin Cohen
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Etienne Pierre-Doray (Gerrit)
Etienne Pierre-Doray voted and added 3 comments![]( "Open in Gerrit")
Votes added by Etienne Pierre-Doray
| Code-Review | +1 |
3 comments
void OSLogTraceSessionObserver::OnSetup(
const perfetto::DataSourceBase::SetupArgs&) {}Nit: TraceSessionObserver has an empty default impl, you don't need to override/define it.
if (thread_id) {
auto thread_track = perfetto::ThreadTrack::ForThread(thread_id);
TRACE_EVENT_INSTANT("ios.os_log.debug",
perfetto::DynamicString(subsystem), thread_track,
timestamp, "message", message);
} else {
TRACE_EVENT_INSTANT("ios.os_log.debug",
perfetto::DynamicString(subsystem),
perfetto::NamedTrack("Unknown Thread"), timestamp,
"message", message);
}Nit:
```
auto thread_track = thread_id ? perfetto::ThreadTrack::ForThread(thread_id) : perfetto::ThreadTrack::Current();
TRACE_EVENT_INSTANT(..., thread_track, ...);
```
Related details
- Justin Cohen
- Justin Novosad
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
No-Unresolved-Comments
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Justin Novosad (Gerrit)
Justin Novosad added 2 comments![]( "Open in Gerrit")
void OSLogTraceSessionObserver::OnSetup(
const perfetto::DataSourceBase::SetupArgs&) {}Nit: TraceSessionObserver has an empty default impl, you don't need to override/define it.
Done
if (thread_id) {
auto thread_track = perfetto::ThreadTrack::ForThread(thread_id);
TRACE_EVENT_INSTANT("ios.os_log.debug",
perfetto::DynamicString(subsystem), thread_track,
timestamp, "message", message);
} else {
TRACE_EVENT_INSTANT("ios.os_log.debug",
perfetto::DynamicString(subsystem),
perfetto::NamedTrack("Unknown Thread"), timestamp,
"message", message);
}Nit:
```
auto thread_track = thread_id ? perfetto::ThreadTrack::ForThread(thread_id) : perfetto::ThreadTrack::Current();TRACE_EVENT_INSTANT(..., thread_track, ...);
```
Unfortunately we can't do that (I had already tried) because we're using different track types in both cases (ThreadTrack vs. NamedTrack). I want to use NamedTrack("Unknown Thread") in the case where thread_id is 0 rather than using ThreadTrack::Current(), which would put the event on the Tracing Muxer thread, which would be misleading.
Related details
- Justin Cohen
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |
Etienne Pierre-Doray (Gerrit)
Etienne Pierre-Doray voted and added 2 comments![]( "Open in Gerrit")
Votes added by Etienne Pierre-Doray
| Code-Review | +1 |
LGTM
if (thread_id) {
auto thread_track = perfetto::ThreadTrack::ForThread(thread_id);
TRACE_EVENT_INSTANT("ios.os_log.debug",
perfetto::DynamicString(subsystem), thread_track,
timestamp, "message", message);
} else {
TRACE_EVENT_INSTANT("ios.os_log.debug",
perfetto::DynamicString(subsystem),
perfetto::NamedTrack("Unknown Thread"), timestamp,
"message", message);
}Justin NovosadNit:
```
auto thread_track = thread_id ? perfetto::ThreadTrack::ForThread(thread_id) : perfetto::ThreadTrack::Current();TRACE_EVENT_INSTANT(..., thread_track, ...);
```
Unfortunately we can't do that (I had already tried) because we're using different track types in both cases (ThreadTrack vs. NamedTrack). I want to use NamedTrack("Unknown Thread") in the case where thread_id is 0 rather than using ThreadTrack::Current(), which would put the event on the Tracing Muxer thread, which would be misleading.
- Justin Cohen
- Justin Novosad
- Rohit Rao
Code-Coverage
Code-Owners
Code-Review
Review-Enforcement
| Inspect html for hidden footers to help with email filtering. To unsubscribe visit settings. |