Inconsistent naming of tracks

[Wallbraker]

I'm having a problem getting the names of tracks to show up consistently.

It seems to me that normally the tracks get the same name as the first event on them, which would be good if I didn't want two different tracks producing the same event name sleep on both client and service. This causes the tracks to merge! Also the events do not show up under the process but instead are loose.

The solution seems to be doing a 1ms sleep after calling PERCETTO_INIT, then registerting the tracks. Then calling TRACE_EVENT_BEGIN_ON_TRACK and TRACE_EVENT_END_ON_TRACK this causes the tracks to get the name from PERCETTO_TRACK_DEFINE not the name of the first event.

[Wallbraker]

An API to name tracks anything other then the name used in say PERCETTO_TRACK_DEFINE would also be nice.

[batesj]

Are you tracing from multiple threads?

Calling TRACE_EVENT_BEGIN_ON_TRACK before PERCETTO_TRACK_DEFINE would be undefined behavior.

Are you starting tracing before starting the process that you are tracing? It looks like there is a bug in that case that could lead to track metadata missing if the track is registered after the first trace event on the same thread. However it looks like things should work if you register just after PERCETTO_INIT.

[Wallbraker]

Yes I'm tracing from multiple threads. What the app does:

• Calls PERCETTO_INIT followed by multiple calls to PERCETTO_REGISTER_TRACK, this is done from a constructor (__attribute__((constructor(101)))) so before my main is called.
• It does a bunch of initialisation this takes about 1 second (to clarify I don't do any tracing until after a second or so).
• The app finally reaches the code that issues TRACE_EVENTs and events to tracks.
• All calls to TRACE_EVENT and tracks are made from static libraries that are not in the compilation unit declaring the tracks.

What I have found:

• PERCETTO_CATEGORY_IS_ENABLED returns false immediately following the calls to PERCETTO_INIT and PERCETTO_REGISTER_TRACK.
• Waiting 1ms is enough to make PERCETTO_CATEGORY_IS_ENABLED return true.
• Doing any kind of tracing, say TRACE_EVENT(category, __func__) in the function that calls PERCETTO_INIT after doing a 1ms sleep is enough to "name" the tracks and have them show up.

[Wallbraker]

The below is the init function, remove the hack part will consistently produce the wrong names for the tracks.

PERCETTO_CATEGORY_DEFINE(U_TRACE_CATEGORIES)

PERCETTO_TRACK_DEFINE(rt_cpu, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_compositor, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_gpu, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_margin, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_error, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_info, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(rt_present, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(ft_cpu, PERCETTO_TRACK_EVENTS);
PERCETTO_TRACK_DEFINE(ft_draw, PERCETTO_TRACK_EVENTS);

void
u_tracer_maker_init(void)
{
    int ret = PERCETTO_INIT(PERCETTO_CLOCK_MONOTONIC);
    if (ret != 0) {
        return;
    }

    I_PERCETTO_TRACK_PTR(rt_cpu)->name = "RT 1 Sleep";
    I_PERCETTO_TRACK_PTR(rt_compositor)->name = "RT 2 Allotted time";
    I_PERCETTO_TRACK_PTR(rt_gpu)->name = "RT 3 GPU";
    I_PERCETTO_TRACK_PTR(rt_margin)->name = "RT 4 Margin";
    I_PERCETTO_TRACK_PTR(rt_error)->name = "RT 5 Error";
    I_PERCETTO_TRACK_PTR(rt_info)->name = "RT 6 Info";
    I_PERCETTO_TRACK_PTR(rt_present)->name = "RT 7 Present";

    I_PERCETTO_TRACK_PTR(ft_cpu)->name = "FT 1 App";
    I_PERCETTO_TRACK_PTR(ft_draw)->name = "FT 2 Draw";

    PERCETTO_REGISTER_TRACK(rt_cpu);
    PERCETTO_REGISTER_TRACK(rt_compositor);
    PERCETTO_REGISTER_TRACK(rt_gpu);
    PERCETTO_REGISTER_TRACK(rt_margin);
    PERCETTO_REGISTER_TRACK(rt_error);
    PERCETTO_REGISTER_TRACK(rt_info);
    PERCETTO_REGISTER_TRACK(rt_present);

    PERCETTO_REGISTER_TRACK(ft_cpu);
    PERCETTO_REGISTER_TRACK(ft_draw);

    /*
     *
     * Hack to get consistent names.
     *
     */

    os_nanosleep(1000 * 1000);

    // But also shows when the app was started.
    XRT_TRACE_MARKER();
}

[batesj]

Could you try a quick test with building against v0.1.3 to see if the bug goes away? I'm wondering if this regressed with f63e7f8ce37289fa23af6a3e1e0ce3b3f08dde2f.

[Wallbraker]

Neither reverting that commit or resetting to v0.1.3 fixes the issue if I leave out that hack.

[Wallbraker]

I am building Percetto in release mode.

[batesj]

I tried to reproduce in a few ways, but did not see any bug.

To rule out incremental state update issues, try adding this to your trace config: incremental_state_config: { clear_period_ms: 500 }

That will force all the perfetto metadata (including track names, ids, etc) to be added to the trace output every 500ms, so if there's just a glitch on the first 500ms then the events should still look correct after that.

If you can share a bad trace and a good trace with me it might help get to the bottom of it. (Could send to me at jbates at chromium.org)

[Wallbraker]

The below is my config, I tried to remove both flush_period_ms and incremental_state_config and that didn't help (also tried DISCARD instead of RING_BUFFER without those to previous mentioned flags and that didn't help either).

flush_period_ms: 30000

incremental_state_config {
    clear_period_ms: 500
}

buffers: {
    size_kb: 63488
    fill_policy: RING_BUFFER
}

data_sources: {
    config: {
        name: "track_event"
        target_buffer: 0
    }
}

[batesj]

Something is wrong with percetto state in your setup. The s_percetto.tracks global data is dumped into each incremental state. In the with_hack trace data that you have, I see s_percetto.tracks correctly dumped in the one incremental state (thanks to your sleep+trace_event), but in subsequent (or prior) ones it looks like s_percetto.tracks is zeroed out. This could happen in a couple ways:

• something is stomping on percetto's global state (seems unlikely).
• same track globals are being shared between multiple percetto instances. This could happen if percetto is linked into multiple shared libraries. In one instance of percetto, custom tracks are registered, but in the other instance, the same tracks are used for tracing but never registered.

If you have multiple shared libraries, percetto/perfetto state can not be shared between them. With the attribute((constructor)) approach in a large codebase might there be some unexpected state/symbol leakage? In your trace, there appear to be two percetto instances, with one defining the tracks and the other tracing on those tracks.

Also percetto/perfetto instances are created for the duration of the process - they don't yet support destruction/shutdown. If you have a dso being loaded and unloaded that could also lead to bugs.

[Wallbraker]

I am pretty sure that there is only a single instance of the track variables and percetto. So it's a executable. I check the symbols and only see one set of my track variables.

Is percetto using any attribute((constructor)) in it's code? Or well static constructors in C++.

[batesj]

Hmm that is strange. Percetto only has POD global data and no use of attribute constructor. I'm not sure about perfetto SDK though.

On Tue, May 4, 2021, 6:57 PM Jakob Bornecrantz @.***> wrote:

I am pretty sure that there is only a single instance of the track variables and percetto. So it's a executable. I check the symbols and only see one set of my track variables.

Is percetto using any attribute((constructor)) in it's code?

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/olvaffe/percetto/issues/15#issuecomment-832364466, or unsubscribe https://github.com/notifications/unsubscribe-auth/AA7QVAF77ZMPELBAAEWRMWLTMCQXBANCNFSM44BDTFAQ .

[Wallbraker]

Yeah something is going on with the fact that I'm using the following code:

#define U_TRACE_TARGET_INIT(WHICH)                                                                                     \
    void __attribute__((constructor(101))) u_trace_maker_constructor(void);                                        \
                                                                                                                       \
    void u_trace_maker_constructor(void)                                                                           \
    {                                                                                                              \
        u_tracer_maker_init(WHICH);                                                                            \
    }

If I put the call of u_trace_marker_init inside of the main function instead it works.

[batesj]

Any shared libraries involved?

[Wallbraker]

I link to a bunch of shared libraries, but none that have any Perfetto/Percetto code.

[Wallbraker]

This turned out to be me initialising Percetto in a c static constructor.