Page MenuHomePhabricator

In "--trace" output, print elapsed miliseconds for ballparking performance issues
ClosedPublic

Authored by epriestley on Aug 3 2018, 10:09 PM.
Tags
None
Referenced Files
F18089716: D19565.id46775.diff
Wed, Aug 6, 12:07 PM
F17944151: D19565.id.diff
Thu, Jul 31, 9:32 AM
F17933938: D19565.diff
Wed, Jul 30, 9:44 PM
Unknown Object (File)
Jul 1 2025, 12:39 PM
Unknown Object (File)
Jun 28 2025, 6:17 PM
Unknown Object (File)
May 7 2025, 8:25 AM
Unknown Object (File)
Apr 29 2025, 9:50 AM
Unknown Object (File)
Apr 27 2025, 7:48 AM
Subscribers
None

Details

Summary

Ref T13164. See PHI766. On PHI766, we saw a slow command on a production host with no ready access to XHProf / --xprofile.

We can reasonably turn --trace into a rough-cut profiler by adding milliseconds-since-start. Then --trace output is good enough to at least roughly ballpark where slowness is happening in many cases. This isn't as good as real profile and won't always be helpful, but at least some of the time it can at least give us enough information to know if, e.g., we should break out the profiler or not.

Test Plan

Ran bin/harbormaster rebuild-log --id ... --trace --force, got milliseconds-since-start in output and some vague idea about where time was being spent.

Diff Detail

Repository
rPHU libphutil
Lint
Lint Not Applicable
Unit
Tests Not Applicable

Event Timeline

amckinley added inline comments.
src/serviceprofiler/PhutilServiceProfiler.php
200

I thought this should have been $elapsed / 1000, but now I've read the docs for microtime(true) and this is why I have trust issues.

This revision is now accepted and ready to land.Aug 3 2018, 10:56 PM
This revision was automatically updated to reflect the committed changes.