Bug 1479301

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.