Event to Span Conversion in Timeline

Up until now the Tideways timeline showed two different kinds of Spans. Regular full-featured spans that each got their own row in the timeline and so-called “span-events” that are directly associated with a span and only store a single name as well as timing information.

This has caused many problems in the UI in the past, and a lack of information, as “span events” did not have stacktraces and could not store additional context annotations.

We have decided migrate all span-events to full-featured spans. The new condensed timeline view will take care of grouping together less-interesting spans, such as simple event listeners for the same event, while giving event listeners with more complex logic the space they deserve.

A timeline before the change looks like this where you can see the events grouped close to the framework span and the details showing both a span and an event on the right:

After the change the UserListener::onKernelRequest is now a full span including stack trace:

Span events have typically been used for events fired by a framework’s event system and also sub-operations where an operation represented by a span consists of several distinct phases that are each interesting on their own. As an example, fetching entities with an ORM might first parse the SQL query internally to analyze it, execute it and then hydrate the entities based on the result.

The direct association of span-events with their associated span would nicely represent this kind of sub-operation in theory. In practice the sub-options would themselves often trigger some other operation that created full spans. In the ORM example, the query execution itself would result in a full SQL span, leading to a mixture of span-events (analyzing the query and hydrating the entities) and spans (executing the query) that made it hard to understand what is happening.

As part of this migration we also looked into additional information to collect:

• The span for an event that was stopped from propagating through further listeners now includes an annotation indicating this.
• For Doctrine the spans for the object hydrator now include an annotation with the number of objects that were hydrated, which directly affects performance.
• Doctrine EntityManager now shows the number of entities checked for changesets
• GraphQL shows more detail in the different resolvers that are run.

The process of migrating all events to spans is underway and has happened for a few instrumentations already and will be completed for all instrumentations over the next few weeks.