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:
Time unit: milliseconds Filed name in log record: elapsedTime
Draft version results in the log - annotating Backend.runAction, Backend.runQuery VmDaoImpl.* methods; Query: 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 Command: 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)
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.
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
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.
(In reply to Yaniv Kaul from comment #5) > Looks good to me. What we need to verify: > 1. It doesn't make sense to enable it unless in DEBUG for all actions. making it DEBUG by default > 2. Nevertheless, for some actions we'd like to see it in INFO level as well. OK so for the default, I'm putting it on DEBUG and expressing the desired log level in the annotation: @InvocationLogger(INFO) public foo(String arg1) { ... }
(In reply to Roy Golan from comment #6) > (In reply to Yaniv Kaul from comment #5) > > Looks good to me. What we need to verify: > > 1. It doesn't make sense to enable it unless in DEBUG for all actions. > making it DEBUG by default > > > 2. Nevertheless, for some actions we'd like to see it in INFO level as well. > OK so for the default, I'm putting it on DEBUG and expressing the desired > log level in the annotation: > > @InvocationLogger(INFO) > public foo(String arg1) { > ... > } OK. Let's see how it works out on ovirt-system-tests and what can we learn from it.
Why is it not in MODIFIED state?
(In reply to Yaniv Kaul from comment #8) > Why is it not in MODIFIED state? I thought gerrit would trigger it. Moving now.
A reproducer would be: 1. set log level to Debug; curl "https://gerrit.ovirt.org/gitweb?p=ovirt-engine.git;a=blob_plain;f=contrib/log-control.sh;hb=HEAD" | bash -s org.ovirt.engine.core DEBUG 2. check the logs for timeElapsed on commands, queries, db interaction, vdsm commands
(In reply to Roy Golan from comment #10) > A reproducer would be: > > 1. set log level to Debug; > curl > "https://gerrit.ovirt.org/gitweb?p=ovirt-engine.git;a=blob_plain;f=contrib/ > log-control.sh;hb=HEAD" | bash -s org.ovirt.engine.core DEBUG > > 2. check the logs for timeElapsed on commands, queries, db interaction, vdsm > commands if that isn't working, just download the script and run it with the 2 arguments "org.ovirt.engine.core DEBUG"
Tested and verified
This bugzilla is included in oVirt 4.2.0 release, published on Dec 20th 2017. Since the problem described in this bug report should be resolved in oVirt 4.2.0 release, published on Dec 20th 2017, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report.