This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 1479301 - [RFE] Add elapsed times of operations to the engine.log
[RFE] Add elapsed times of operations to the engine.log
Status: ON_QA
Product: ovirt-engine
Classification: oVirt
Component: Backend.Core (Show other bugs)
4.2.0
Unspecified Unspecified
unspecified Severity medium (vote)
: ovirt-4.2.0
: 4.2.0
Assigned To: Roy Golan
meital avital
: FutureFeature, Performance
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-08-08 06:35 EDT by Roy Golan
Modified: 2017-10-02 09:58 EDT (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
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;

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)
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.
Comment 6 Roy Golan 2017-09-05 02:20:48 EDT
(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) {
    ...
  }
Comment 7 Yaniv Kaul 2017-09-05 02:44:59 EDT
(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.
Comment 8 Yaniv Kaul 2017-09-26 05:56:58 EDT
Why is it not in MODIFIED state?
Comment 9 Roy Golan 2017-09-26 06:46:09 EDT
(In reply to Yaniv Kaul from comment #8)
> Why is it not in MODIFIED state?

I thought gerrit would trigger it. Moving now.
Comment 10 Roy Golan 2017-09-26 11:14:21 EDT
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
Comment 11 Roy Golan 2017-10-02 08:59:00 EDT
(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"

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