History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: QB-3054
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Critical Critical
Assignee: Unassigned
Reporter: Piotr Jedrys
Votes: 0
Watchers: 1
Operations

If you were logged in you would be able to see more operations.
QuickBuild

Measurement data missing after QuickBuild upgrade to 7.0.16

Created: 03/Oct/17 10:09 AM   Updated: 13/Oct/17 10:54 AM
Component/s: None
Affects Version/s: None
Fix Version/s: 7.0.25

Original Estimate: Unknown Remaining Estimate: Unknown Time Spent: Unknown


 Description  « Hide
After upgrading from QuickBuild 6.0.x to QuickBuild 7.0.16, we found out that metrics are not working anymore. The problem is because of :

Duplicate entry '1507021838789-xxx:8810-disk.usage./opt/quic' for key 'PK_DATA_R04'
quickbuild_master_1 | jvm 1 | Query is: /* insert com.pmease.quickbuild.model.MeasurementDataR04 */ insert into QB_MEASUREMENT_DATAR04 (QB_METRIC_NAME, QB_SOURCE, QB_TIMESTAMP, QB_VALUE, QB_ID) values (?, ?, ?, ?, ?), parameters ['disk.usage./opt/quickbuild','xxx:8810',1507021838789,0.1307280165131342,21857]

the strangest part is that the table is empty:
mysql> select * from QB_MEASUREMENT_DATAR04;
Empty set (0.00 sec)

and the manual insert works correctly:
mysql> insert into QB_MEASUREMENT_DATAR04 (QB_METRIC_NAME, QB_SOURCE, QB_TIMESTAMP, QB_VALUE, QB_ID) values ('disk.usage./opt/quickbuild','xxx:8810',1507021838789,0.1307280165131342,21857);
Query OK, 1 row affected (0.00 sec)

mysql> select * from QB_MEASUREMENT_DATAR04; +-------+----------------------------+-------------------------------+---------------+--------------------+
| QB_ID | QB_METRIC_NAME | QB_SOURCE | QB_TIMESTAMP | QB_VALUE |
+-------+----------------------------+-------------------------------+---------------+--------------------+
| 21857 | disk.usage./opt/quickbuild | xxx:8810 | 1507021838789 | 0.1307280165131342 |
+-------+----------------------------+-------------------------------+---------------+--------------------+
1 row in set (0.00 sec)


 All   Comments   Work Log   Change History      Sort Order:
Piotr Jedrys [03/Oct/17 11:00 AM]
Adding stacktrace just in case:

jvm 1 | source=[xxx:8810], metricName=[network.rxBytes], timestamp=[Tue Oct 03 10:53:44 UTC 2017], value=[1078923.0] to handler [wrapper public void com.pmease.quickbuild.plugin.measurement.core.reporter.AbstractReporter.onReportReceived(com.pmease.quickbuild.plugin.measurement.core.extensionpoint.NodeMeasurementReport)]
jvm 1 | java.lang.reflect.InvocationTargetException
jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
jvm 1 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
jvm 1 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
jvm 1 | at java.lang.reflect.Method.invoke(Method.java:606)
jvm 1 | at com.google.common.eventbus.EventHandler.handleEvent(EventHandler.java:74)
jvm 1 | at com.google.common.eventbus.SynchronizedEventHandler.handleEvent(SynchronizedEventHandler.java:45)
jvm 1 | at com.google.common.eventbus.EventBus.dispatch(EventBus.java:313)
jvm 1 | at com.google.common.eventbus.EventBus.dispatchQueuedEvents(EventBus.java:296)
jvm 1 | at com.google.common.eventbus.EventBus.post(EventBus.java:267)
jvm 1 | at com.pmease.quickbuild.plugin.measurement.core.poller.MeasurementPollingTask.execute(MeasurementPollingTask.java:56)
jvm 1 | at com.pmease.quickbuild.plugin.measurement.core.poller.MeasurementPollingTask.run(MeasurementPollingTask.java:108)
jvm 1 | at com.google.common.util.concurrent.AbstractExecutionThreadService$1$1.run(AbstractExecutionThreadService.java:52)
jvm 1 | at java.lang.Thread.run(Thread.java:748)
jvm 1 | Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement
jvm 1 | at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:72)
jvm 1 | at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
jvm 1 | at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126)
jvm 1 | at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112)
jvm 1 | at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:211)
jvm 1 | at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62)
jvm 1 | at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3124)
jvm 1 | at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3581)
jvm 1 | at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:104)
jvm 1 | at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:465)
jvm 1 | at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:351)
jvm 1 | at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350)
jvm 1 | at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)
jvm 1 | at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1258)
jvm 1 | at com.pmease.quickbuild.entitymanager.impl.DefaultMeasurementDataManager.flushAndClear(DefaultMeasurementDataManager.java:76)
jvm 1 | at com.pmease.quickbuild.entitymanager.impl.DefaultMeasurementDataManager.save(DefaultMeasurementDataManager.java:103)
jvm 1 | at com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter.save(MeasurementServerReporter.java:105)
jvm 1 | at com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter.run(MeasurementServerReporter.java:76)
jvm 1 | at com.pmease.quickbuild.plugin.measurement.core.reporter.AbstractReporter.onReportReceived(AbstractReporter.java:12)
jvm 1 | ... 13 more
jvm 1 | Caused by: java.sql.SQLIntegrityConstraintViolationException: Duplicate entry...

Steve Luo [05/Oct/17 10:34 AM]
Hi Piotr,

Please add below line to your node log4j file: conf/log4j.properties

log4j.logger.com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter=DEBUG

then after some time, please find below pattern in the node log: Sending measurement data report
where you will see the details about the measurement reports and please confirm if there is any duplication in the report.

Piotr Jedrys [06/Oct/17 09:47 AM]
Log from the node:

jvm 4 | 2017-10-06 11:37:16,815 DEBUG - Sending measurement data report [Node: [plsrvmp-qbs19:8811], beginTime: [Fri Oct 06 11:37:15 CEST 2017], endTime: [Fri Oct 06 11:37:16 CEST 2017]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[jvm.memoryUsage], timestamp=[Fri Oct 06 11:37:15 CEST 2017], value=[0.0766898126339434]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[cpu.totalUsage], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.017543859649122806]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[memory.usage], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.2718772888183594]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[steps.finishedOnNode], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.0]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[steps.successfulOnNode], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.0]] to server ...
jvm 4 | 2017-10-06 11:37:17,083 ERROR - Could not dispatch event: Node: [plsrvmp-qbs19:8811], beginTime: [Fri Oct 06 11:37:15 CEST 2017], endTime: [Fri Oct 06 11:37:16 CEST 2017]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[jvm.memoryUsage], timestamp=[Fri Oct 06 11:37:15 CEST 2017], value=[0.0766898126339434]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[cpu.totalUsage], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.017543859649122806]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.usage./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.25779120912919257]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[disk.frees./], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[7.41460594688E11]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[memory.usage], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.2718772888183594]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[steps.finishedOnNode], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.0]
jvm 4 | source=[plsrvmp-qbs19:8811], metricName=[steps.successfulOnNode], timestamp=[Fri Oct 06 11:37:16 CEST 2017], value=[0.0] to handler [wrapper public void com.pmease.quickbuild.plugin.measurement.core.reporter.AbstractReporter.onReportReceived(com.pmease.quickbuild.plugin.measurement.core.extensionpoint.NodeMeasurementReport)]
jvm 4 | java.lang.reflect.InvocationTargetException
jvm 4 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
jvm 4 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
jvm 4 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
jvm 4 | at java.lang.reflect.Method.invoke(Method.java:498)
jvm 4 | at com.google.common.eventbus.EventHandler.handleEvent(EventHandler.java:74)
jvm 4 | at com.google.common.eventbus.SynchronizedEventHandler.handleEvent(SynchronizedEventHandler.java:45)
jvm 4 | at com.google.common.eventbus.EventBus.dispatch(EventBus.java:313)
jvm 4 | at com.google.common.eventbus.EventBus.dispatchQueuedEvents(EventBus.java:296)
jvm 4 | at com.google.common.eventbus.EventBus.post(EventBus.java:267)
jvm 4 | at com.pmease.quickbuild.plugin.measurement.core.poller.MeasurementPollingTask.execute(MeasurementPollingTask.java:56)
jvm 4 | at com.pmease.quickbuild.plugin.measurement.core.poller.MeasurementPollingTask.run(MeasurementPollingTask.java:108)
jvm 4 | at com.google.common.util.concurrent.AbstractExecutionThreadService$1$1.run(AbstractExecutionThreadService.java:52)
jvm 4 | at java.lang.Thread.run(Thread.java:745)
jvm 4 | Caused by: java.lang.RuntimeException: Error executing node job execute job.
jvm 4 | at com.pmease.quickbuild.grid.NodeJobExecuteTask.reduce(NodeJobExecuteTask.java:32)
jvm 4 | at com.pmease.quickbuild.grid.NodeJobExecuteTask.reduce(NodeJobExecuteTask.java:10)
jvm 4 | at com.pmease.quickbuild.grid.GridTaskFuture.get(GridTaskFuture.java:116)
jvm 4 | at com.pmease.quickbuild.grid.GridTaskFuture.get(GridTaskFuture.java:120)
jvm 4 | at com.pmease.quickbuild.grid.GridNode.executeJob(GridNode.java:491)
jvm 4 | at com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter.run(MeasurementServerReporter.java:79)
jvm 4 | at com.pmease.quickbuild.plugin.measurement.core.reporter.AbstractReporter.onReportReceived(AbstractReporter.java:12)
jvm 4 | ... 13 more
jvm 4 | Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement
jvm 4 | at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:72)
jvm 4 | at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
jvm 4 | at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126)
jvm 4 | at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112)
jvm 4 | at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:211)
jvm 4 | at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62)
jvm 4 | at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3124)
jvm 4 | at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3581)
jvm 4 | at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:104)
jvm 4 | at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:465)
jvm 4 | at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:351)
jvm 4 | at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350)
jvm 4 | at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)
jvm 4 | at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1258)
jvm 4 | at com.pmease.quickbuild.entitymanager.impl.DefaultMeasurementDataManager.flushAndClear(DefaultMeasurementDataManager.java:76)
jvm 4 | at com.pmease.quickbuild.entitymanager.impl.DefaultMeasurementDataManager.save(DefaultMeasurementDataManager.java:103)
jvm 4 | at com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter.save(MeasurementServerReporter.java:105)
jvm 4 | at com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter.access$100(MeasurementServerReporter.java:34)
jvm 4 | at com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter$NodeMetricsSender.execute(MeasurementServerReporter.java:93)
jvm 4 | at com.pmease.quickbuild.grid.NodeJobExecuteJob.execute(NodeJobExecuteJob.java:25)
jvm 4 | at com.pmease.quickbuild.grid.GridJob.run(GridJob.java:106)
jvm 4 | at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473)
jvm 4 | at java.util.concurrent.FutureTask.run(FutureTask.java:262)
jvm 4 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
jvm 4 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
jvm 4 | at java.lang.Thread.run(Thread.java:748)
jvm 4 | Caused by: java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '1507282636652-plsrvmp-qbs19:8811-disk.usage./' for key 'PK_DATA_R00'
jvm 4 | Query is: /* insert com.pmease.quickbuild.model.MeasurementDataR00 */ insert into QB_MEASUREMENT_DATAR00 (QB_METRIC_NAME, QB_SOURCE, QB_TIMESTAMP, QB_VALUE, QB_ID) values (?, ?, ?, ?, ?), parameters ['disk.usage./','plsrvmp-qbs19:8811',1507282636652,0.25779120912919257,95]
jvm 4 | at org.mariadb.jdbc.internal.util.ExceptionMapper.get(ExceptionMapper.java:119)
jvm 4 | at org.mariadb.jdbc.internal.util.ExceptionMapper.throwException(ExceptionMapper.java:69)
jvm 4 | at org.mariadb.jdbc.MariaDbStatement.executeQueryEpilog(MariaDbStatement.java:226)
jvm 4 | at org.mariadb.jdbc.MariaDbServerPreparedStatement.executeInternal(MariaDbServerPreparedStatement.java:376)
jvm 4 | at org.mariadb.jdbc.MariaDbServerPreparedStatement.execute(MariaDbServerPreparedStatement.java:323)
jvm 4 | at org.mariadb.jdbc.MariaDbServerPreparedStatement.executeUpdate(MariaDbServerPreparedStatement.java:312)
jvm 4 | at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:147)
jvm 4 | at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:208)
jvm 4 | ... 21 more


As for the database on the QuickBuild master server, I cannot see any measurement data in the QB_MEASUREMENT_DATAR00 table:

mysql> select * from QB_MEASUREMENT_DATAR00;
Empty set (0.00 sec)

Piotr Jedrys [13/Oct/17 10:54 AM]
Any comment on it? Is it resolved in the newer version? How can we ommit it in the current version.