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
Unknown Object (File)
Fri, Apr 19, 7:51 PM
Unknown Object (File)
Thu, Apr 11, 10:50 AM
Unknown Object (File)
Fri, Apr 5, 3:49 PM
Unknown Object (File)
Mar 2 2024, 7:34 AM
Unknown Object (File)
Feb 14 2024, 12:36 PM
Unknown Object (File)
Feb 2 2024, 2:50 PM
Unknown Object (File)
Jan 10 2024, 1:14 PM
Unknown Object (File)
Jan 5 2024, 5:38 PM
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.