Page MenuHomePhabricator

Improve sequencing of Futures in "--trace" output
Open, LowPublic

Description

See PHI2021. An example of arc diff --trace shows somewhat-misleading sequence when resolving a future:

>>> [75] (+11,785) <http> https://phabricator.example.com/api/differential.creatediff
<<< [75] (+12,288) <http> 502,777 us
>>> [76] (+12,288) <conduit> differential.creatediff() <bytes = 641,018>
<<< [76] (+12,288) <conduit> 44 us

( ... other events ...)

[2021-03-09 19:47:09] EXCEPTION: (HTTPFutureHTTPResponseStatus) [HTTP/500] Internal Server Error at [<arcanist>/src/future/http/BaseHTTPFuture.php:382]

This would likely be more clear as:

>>> conduit
  >>> http
  <<< http [!]
<<< conduit [!]

...

+++ conduit [!]

...where some of these are true:

  • FutureProxies start first and end last in trace output;
  • proxied futures get indented;
  • futures that are ready to resolve, but will throw when resolved, are marked differently;
  • future resolution events are marked.

Some of these may be tricky or questionable for performance reasons, but the current sequence isn't great and any easy improvements that are available would be nice.

Event Timeline

epriestley created this task.

See also T13646: some very early service calls during initialization currently occur before --trace becomes active. These calls should be visible, possibly by buffering them and then dumping the buffer once --trace comes online.