Trace duration of classpath container updates#2374
Conversation
|
AFAICS neither the licence check nor the new maven warnings (None touch pde.core. These appear in PR builds but not in the stale reference build #215, so warnings-ng flags them as "new".) are related to this PR. |
|
/request-license-review |
✔️ All licenses already successfully vetted. Workflow run (with attached summary files): |
vogella
force-pushed
the
pde-classpath-update-tracing
branch
from
d22b77d to
8e988ef
Compare
|
|
||
| @Override | ||
| protected IStatus run(IProgressMonitor jobMonitor) { | ||
| long startNanos = PDECore.DEBUG_CLASSPATH ? System.nanoTime() : 0; |
There was a problem hiding this comment.
Since the output is in milliseconds, wouldn't it be suitable to use milliseconds from the beginning?
There was a problem hiding this comment.
The traceRuntime helper keeps nanoTime() and only divides to ms at the end, so the durations stay monotonic (immune to wall-clock adjustments) while the output is in ms as before. Let me know if you'd still prefer currentTimeMillis().
There was a problem hiding this comment.
the durations stay monotonic (immune to wall-clock adjustments)
Have to admit that I haven’t considered that. I'd say that if one modifies a computer's clock it's acceptable to have wrong time recordings in tracing and System.currentTimeMillis() is sufficient (and a bit simpler).
But I'm also fine to keep it, no strict opposition from my side.
HannesWell
left a comment
HannesWell
left a comment
There was a problem hiding this comment.
This should be useful to gather more performance data.
Besides the mentioned use of milliseconds I think the repeating tracing code can be unified.
Please see my comment below.
With that applied I'm fine with this.
| private static long elapsedMillis(long startNanos) { | ||
| return (System.nanoTime() - startNanos) / 1_000_000L; | ||
| } | ||
|
|
There was a problem hiding this comment.
The invocation of this uses a repeating pattern, which I suggest to unify to something
| private static long elapsedMillis(long startNanos) { | |
| return (System.nanoTime() - startNanos) / 1_000_000L; | |
| } | |
| private void traceRuntime(String msg, long start, Object... args) { | |
| if (PDECore.DEBUG_CLASSPATH) { | |
| long elapsedMillis = (System.nanoTime() - start) / 1_000_000L; | |
| Object[] allArgs = Stream.concat(Stream.of(elapsedMillis), Stream.of(args)).toArray(); | |
| PDECore.TRACE.trace(PDECore.KEY_DEBUG_CLASSPATH, String.format(msg, allArgs)); | |
| } | |
| } |
Which can then be called with (almost) one-liners:
traceRuntime("Computed classpath of %2$d project(s) in %1$d ms.", computeNanos, count); //$NON-NLS-1$- traceRuntime("Applied classpath container of %2$d project(s) in %1$d ms.", applyNanos, n); //$NON-NLS-1$
traceRuntime("UpdateClasspathsJob finished in %d ms: %d request(s), %d updated, %d error(s).", startNanos, count, updateProjects.size(), errorsPerProject.size()); //$NON-NLS-1$
There was a problem hiding this comment.
Applied, thanks. Folded the three trace blocks into your traceRuntime helper and dropped the separate elapsedMillis method.
vogella
force-pushed
the
pde-classpath-update-tracing
branch
from
8e988ef to
140b5a7
Compare
vogella
force-pushed
the
pde-classpath-update-tracing
branch
from
140b5a7 to
c4a1b2a
Compare
|
Build failure seem unrelated. |
See #2380 (comment). |
Add duration tracing to the UpdateClasspathsJob, gated behind the existing org.eclipse.pde.core/classpath debug option. The trace reports the time spent computing the classpath entries, applying the containers to the Java model, and the overall job, so slow classpath updates can be diagnosed without a profiler.
HannesWell
force-pushed
the
pde-classpath-update-tracing
branch
from
c4a1b2a to
74949c2
Compare
2 participants
Adds duration tracing to the PDE classpath update job (
UpdateClasspathsJob), gated behind the existingorg.eclipse.pde.core/classpathdebug option. When enabled, the job traces how long it spent computing the classpath entries, applying the containers to the Java model, and the overall run. This makes it possible to diagnose slow classpath updates from the trace output alone, without attaching a profiler. No behavior changes when tracing is off.