| << Back to previous view |
|
[QB-3054] Measurement data missing after QuickBuild upgrade to 7.0.16
|
|
| Status: | Resolved |
| Project: | QuickBuild |
| Component/s: | None |
| Affects Version/s: | None |
| Fix Version/s: | 7.0.25 |
| Type: | Bug | Priority: | Critical |
| Reporter: | Piotr Jedrys | Assigned To: | Unassigned |
| Resolution: | Fixed | Votes: | 0 |
| Remaining Estimate: | Unknown | Time Spent: | Unknown |
| Original Estimate: | Unknown | ||
| Description |
|
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) |
| Comments |
| Comment by 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... |
| Comment by 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. |
| Comment by 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) |
| Comment by 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. |