Page MenuHomeSoftware Heritage

Add logging of endpoint timing
ClosedPublic

Authored by haltode on Jul 19 2019, 4:05 PM.

Details

Summary

Closes T1921.

Diff Detail

Repository
rDGRPH Compressed graph representation
Branch
timings-logger
Lint
No Linters Available
Unit
No Unit Test Coverage
Build Status
Buildable 7053
Build 9934: arc lint + arc unit

Event Timeline

zack requested changes to this revision.Jul 19 2019, 4:13 PM

E_TOO_MUCH_CODE_DUPLICATION :-)

Instead of this, please add a pair of private methods to the Endpoint class, one to start timing (e.g., this.startTiming()), one to end it and return the diff w.r.t. the start time (e.g., this.stopTiming()) , and make all endpoint methods invoke the two methods and log the result.

(In theory you could even refactor the last line to avoid having a logger.debug statement in each method, and delegate that to stopTiming, but that would require introspection and it'd be hard to do in a thread-safe way; so it's probably not worth the effort)

This revision now requires changes to proceed.Jul 19 2019, 4:13 PM
java/server/src/main/java/org/softwareheritage/graph/Endpoint.java
74–75

Also, outputing ns is going to be a pain more often than not.

If there is an easy way to adaptively format things (e.g., compute seconds, and output them as s/ms/ns/us depending on what's the most compact), that would be ideal.

Alternatively, just compute seconds and output a float using scientific notations (clamped to powers of 3, if supported by format strings).

Remove code duplication.

java/server/src/main/java/org/softwareheritage/graph/Endpoint.java
74–75

Slf4j does not support string formatting inside the {}, so I left the default double formatting from Java (which uses scientific notation).

zack requested changes to this revision.Jul 19 2019, 5:04 PM
zack added inline comments.
java/server/src/main/java/org/softwareheritage/graph/Endpoint.java
26–31

I'm missing some info to judge if this is OK or not: is the Endpoint class instantiated only once per endpoint, or is it instantiated once per request, when the swh-graph will be running? If it's instantiated once per endpoint, it is possible that multiple threads will be executing the same endpoint at the same time, and this will mess up this way of counting duration, as different threads will step on each others toes.

Can you check this?

(see also below for a suggestion of how to make this more functional, which will make the issue moot anyway)

69–75

you can make this more functional, like this:

long ts = this.startTiming();
...
float duration = this.stopTiming(ts);
logger.debug("....", duration)

it will remove any state from the object instance, fixing the thread-safety issue.

(the right design here would be to make both ts and duration opaque objects, with duration having a pretty print method, but this is probably overkill for now :-))

This revision now requires changes to proceed.Jul 19 2019, 5:04 PM

Use local variables instead of class variable (more functional and fix
multithreading issues).

This revision is now accepted and ready to land.Jul 29 2019, 9:45 AM

Closed by commit ebfa6310c5ab.