Bug 1373456 - Debug message for start and end of DWH heartbeat
Summary: Debug message for start and end of DWH heartbeat
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: Database.Core
Version: 4.1.0
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ovirt-4.0.5
: 4.0.5
Assignee: Eli Mesika
QA Contact: Lukas Svaty
URL:
Whiteboard:
Depends On: 1371111 1430666
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-09-06 10:36 UTC by Shirly Radco
Modified: 2017-03-09 09:22 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1371111
Environment:
Last Closed: 2017-01-18 07:39:53 UTC
oVirt Team: Infra
Embargoed:
rule-engine: ovirt-4.0.z+
mgoldboi: planning_ack+
rule-engine: devel_ack+
pstehlik: testing_ack+


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 64139 0 master MERGED core: adding debug message to DWH heart beat 2016-09-19 15:47:01 UTC
oVirt gerrit 64191 0 ovirt-engine-4.0 MERGED core: adding debug message to DWH heart beat 2016-09-20 12:53:11 UTC

Description Shirly Radco 2016-09-06 10:36:58 UTC
+++ This bug was initially created as a clone of Bug #1371111 +++

Description of problem:
Engine Heartbeat should update every 15 seconds, but in some cases it may take longer than 20 seconds.
If it takes longer than 20 seconds the dwh will alert
"Can not sample data, oVirt Engine is not updating the statistics" .

Version-Release number of selected component (if applicable):
4.0.2

How reproducible:

Steps to Reproduce:
1.Try to load the engine machine with dwh installed.
2.
3.

Actual results:
Hearbeat does not update every 15 seconds and can take longer than 20 seconds.

Expected results:
Hearbeat should update every 15 seconds.

Additional info:

Comment 1 Eli Mesika 2016-09-11 10:37:44 UTC
This is a normal scheduler job in DwhHeartBeat.java
I checked the engine log in rhev-tlv today and did not found this issue 
Anyway, there are two options here 

Either it is a scheduler issue or it is a DB issue 
I recommend to add some logging in order to determine who is responsible for that delay 

The code is :

public void engineIsRunningNotification() {
        try {
            // TODO : add logging here
            heartBeatVar.setDateTime(new Date());
            dwhHistoryTimekeepingDao.save(heartBeatVar);
            // TODO : add logging here
        } catch (Exception ex) {
            log.error("Error updating DWH Heart Beat: {}", ex.getMessage());
            log.debug("Exception", ex);
        }
    }
}

See my TODO comments inside the code, this will enable us at least to track the log and see the invocation time as well as the time this change was saved to the database

Comment 2 Oved Ourfali 2016-09-15 05:34:58 UTC
Reducing severity, as it will be treated also via Bug #1371111.
I agree with Eli that logging will indeed help here analyze the issue.

Comment 3 Yaniv Kaul 2016-09-19 12:42:19 UTC
(In reply to Eli Mesika from comment #1)
> This is a normal scheduler job in DwhHeartBeat.java
> I checked the engine log in rhev-tlv today and did not found this issue 

It happens several times a day in RHEV.TLV.

Comment 4 Martin Perina 2016-09-22 13:00:17 UTC
We have added additional logging to find out what causes the issue/

Comment 5 Eli Mesika 2016-10-05 07:21:02 UTC
(In reply to Martin Perina from comment #4)
> We have added additional logging to find out what causes the issue/

Please note that new log messages are DEBUG messages , so you have to turn on the DEBUG logging mode

Comment 6 Lukas Svaty 2016-10-13 08:48:26 UTC
verified in ovirt-engine-4.0.5-0.1.el7ev.noarch

2016-10-13 10:47:18,627 INFO  [org.ovirt.engine.core.bll.dwh.DwhHeartBeat] (ServerService Thread Pool -- 67) [] Initializing DWH Heart Beat
2016-10-13 10:47:18,628 INFO  [org.ovirt.engine.core.bll.dwh.DwhHeartBeat] (ServerService Thread Pool -- 67) [] DWH Heart Beat initialized
2016-10-13 10:47:18,628 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (ServerService Thread Pool -- 67) [] Start org.ovirt.engine.core.bll.dwh.DwhHeartBeat@31cb7143 
2016-10-13 10:47:18,650 DEBUG [org.ovirt.engine.core.bll.dwh.DwhHeartBeat] (DefaultQuartzScheduler4) [] DWH Heart Beat - Start
2016-10-13 10:47:18,696 DEBUG [org.ovirt.engine.core.bll.dwh.DwhHeartBeat] (DefaultQuartzScheduler4) [] DWH Heart Beat - End
2016-10-13 10:47:33,697 DEBUG [org.ovirt.engine.core.bll.dwh.DwhHeartBeat] (DefaultQuartzScheduler8) [] DWH Heart Beat - Start
2016-10-13 10:47:33,703 DEBUG [org.ovirt.engine.core.bll.dwh.DwhHeartBeat] (DefaultQuartzScheduler8) [] DWH Heart Beat - End
2016-10-13 10:47:48,705 DEBUG [org.ovirt.engine.core.bll.dwh.DwhHeartBeat] (DefaultQuartzScheduler2) [] DWH Heart Beat - Start
2016-10-13 10:47:48,712 DEBUG [org.ovirt.engine.core.bll.dwh.DwhHeartBeat] (DefaultQuartzScheduler2) [] DWH Heart Beat - End


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