Bug 1479301 - [RFE] Add elapsed times of operations to the engine.log
[RFE] Add elapsed times of operations to the engine.log
Status: POST
Product: ovirt-engine
Classification: oVirt
Component: Backend.Core (Show other bugs)
Unspecified Unspecified
unspecified Severity medium (vote)
: ovirt-4.2.0
: ---
Assigned To: Roy Golan
meital avital
: FutureFeature, Performance
Depends On:
  Show dependency treegraph
Reported: 2017-08-08 06:35 EDT by Roy Golan
Modified: 2017-08-21 08:34 EDT (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
Verified Versions:
Category: ---
oVirt Team: Infra
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
mperina: ovirt‑4.2?
rule-engine: planning_ack?
mperina: devel_ack+
rule-engine: testing_ack?

Attachments (Terms of Use)

External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 80636 master POST core: Log invocation times using Logging Interceptor 2017-08-15 05:42 EDT

  None (edit)
Description Roy Golan 2017-08-08 06:35:14 EDT
Description of problem:
Backend actions in the log doesn't say explicitly how much time they take. We do of course have timestamps, but we can do better:

It would be nice if could see this on the START and FINISH log messages:

  19:00:00 INFO [3eea835b] START, AddVdsVDSCommand(HostName = some.host) 
  19:00:05 INFO [3eea835b] FINISH, AddVdsVDSCommand elapsed:5000

And we that we would be able to graph and analyze etc.

Which actions gets measurements:
 - Backend API calls - i.e Commands, Queries.  - INFO
 - VDSM API calls                              - INFO
 - Threads                                     - DEBUG

Implementation notes:
Usage of CDI interceptors would be very handy here(already have correlation id interceptor). For threads need to see how can we interact with the ManagedExecutor to achieve this.

Actual results:
We don't have and explicit log entry of how much time actions takes.

Expected results:
Commands, Queries, VDSM commands and threads execution gets 'elapsed:Nms' addition to the log

Additional info:
Comment 1 Roy Golan 2017-08-08 06:38:56 EDT
Time unit: milliseconds
Filed name in log record: elapsedTime
Comment 2 Roy Golan 2017-08-15 04:43:33 EDT
Draft version results in the log - annotating Backend.runAction, Backend.runQuery VmDaoImpl.* methods;

2017-08-15 11:37:53,156+03 INFO  [org.ovirt.engine.core.common.di.interceptor.ElapsedTimeInterceptor] (default task-4) [] method: runQuery, params: [Search, SearchParameters:{refresh='false', filtered='false', searchType='VM', searchPattern='Vms:', caseSensitive='true', from='0', max='100'}], elapsed: 0ms

2017-08-15 11:36:59,306+03 INFO  [org.ovirt.engine.core.common.di.interceptor.ElapsedTimeInterceptor] (DefaultQuartzScheduler8) [20aa8160] method: getVmsByIds, params: [[]], elapsed: 15ms

VM table access:
2017-08-15 11:36:59,306+03 INFO  [org.ovirt.engine.core.common.di.interceptor.ElapsedTimeInterceptor] (DefaultQuartzScheduler8) [20aa8160] method: getVmsByIds, params: [[]], elapsed: 15ms

- currently it is INFO, but should be DEBUG level
- more flows to consider intercepting: vdsm API interaction, host/vm monitoring, thread invocations(overlaps with Command intercepting obviously)
Comment 3 Roy Golan 2017-08-15 04:45:06 EDT
paste mistake, the command logging looks like that:

2017-08-15 11:38:42,529+03 INFO  [org.ovirt.engine.core.common.di.interceptor.ElapsedTimeInterceptor] (default task-64) [523f15a1] method: run
Action, params: [CreateUserSession, CreateUserSessionParameters:{commandId='4bd6657d-b7a3-4c5c-b2b8-d86b0b5bb87b', user='null', commandType='U
nknown'}], elapsed: 123ms

123ms looks like a lot of time(!) btw for a login.
Comment 4 Roy Golan 2017-08-15 04:59:16 EDT
VDSM interaction (get all task info verb):
2017-08-15 11:58:16,580+03 INFO  [org.ovirt.engine.core.common.di.interceptor.ElapsedTimeInterceptor] (org.ovirt.thread.EE-ManagedThreadFactory-engine-Thread-4) [15193219] method: runVdsCommand, params: [SPMGetAllTasksInfo, IrsBaseVDSCommandParameters:{storagePoolId='59929ea3-01f5-021c-0158-00000000026a', ignoreFailoverLimit='false'}], elapsed: 17ms
Comment 5 Yaniv Kaul 2017-08-15 10:56:02 EDT
Looks good to me. What we need to verify:
1. It doesn't make sense to enable it unless in DEBUG for all actions.
2. Nevertheless, for some actions we'd like to see it in INFO level as well.

Note You need to log in before you can comment on or make changes to this bug.