dhis2-users team mailing list archive
-
dhis2-users team
-
Mailing list archive
-
Message #02174
Issue with Datamart export
Dear all,
I face an issue with Datamart export.Sent this message to user list
earlier.
*Server: *
Build revision: 9149 Build date:2013-03-27 13:41User agent: Mozilla/5.0
(Windows NT 6.1; WOW64; rv:20.0) Gecko/20100101 Firefox/20.0External
configuration directory:Not setEnvironment variable:DHIS2_HOMEDatabase type:
MySQL Java Opts:-Xms256m -Xmx1512m -XX:PermSize=128m -XX:MaxPermSize=512m
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManagerJava
version:1.6.0_24Java vendor:Sun Microsystems Inc. OS name:LinuxOS
architecture:amd64OS version:3.2.0-29-genericServer date:2013-04-25 23:59Server
memory:Mem Total in JVM: 846 Free in JVM: 403 Max Limit: 1344 CPU
cores:4*Tomcat
log: *
* INFO 2013-04-25 07:54:05,856 Using periods: [[Monthly: Sat Dec 01
00:00:00 IST 2012 - Mon Dec 31 00:00:00 IST 2012], [Quarterly: Mon Oct 01
00:00:00 IST 2012 - Mon Dec 31 00:00:00 IST 2012]] (DataMartTask.java
[taskScheduler-5])
* INFO 2013-04-25 07:54:06,159 Data mart export process started, number of
CPU cores: 4, Mem Total in JVM: 622 Free in JVM: 389 Max Limit: 1344:
0:00:00.000 (Clock.java [taskScheduler-5])
* INFO 2013-04-25 07:54:06,162 [Level: INFO, category: DATAMART, time: Thu
Apr 25 07:54:06 IST 2013, message: Data mart export process started]
(InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-25 07:54:07,206 Recreated temporary tables: 0:00:01.047
(Clock.java [taskScheduler-5])
* INFO 2013-04-25 07:54:07,206 Data elements: 1228, indicators: 294,
periods: 2, org units: 1296: 0:00:01.047 (Clock.java [taskScheduler-5])
* INFO 2013-04-25 07:54:07,426 Retrieved meta-data objects, using periods:
[[Quarterly: 2012-10-01 - 2012-12-31], [Monthly: 2012-12-01 - 2012-12-31]]:
0:00:01.267 (Clock.java [taskScheduler-5])
* INFO 2013-04-25 07:54:07,426 [Level: INFO, category: DATAMART, time: Thu
Apr 25 07:54:07 IST 2013, message: Filtering meta-data]
(InMemoryNotifier.java [taskScheduler-5])
* WARN 2013-04-25 07:54:07,565 Indicator is invalid: [Number of Dental
Surgeons per 10,000 population] (DefaultExpressionService.java
[taskScheduler-5])
* INFO 2013-04-25 07:54:07,716 Filtered objects: 0:00:01.557 (Clock.java
[taskScheduler-5])
* INFO 2013-04-25 07:54:07,717 [Level: INFO, category: DATAMART, time: Thu
Apr 25 07:54:07 IST 2013, message: Loading indicators]
(InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-25 07:54:07,727 Exploded indicator expressions: 0:00:01.568
(Clock.java [taskScheduler-5])
* INFO 2013-04-25 07:54:07,727 [Level: INFO, category: DATAMART, time: Thu
Apr 25 07:54:07 IST 2013, message: Loading data elements]
(InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-25 07:54:12,094 Retrieved operands: 1493: 0:00:05.935
(Clock.java [taskScheduler-5])
* INFO 2013-04-25 07:54:12,095 [Level: INFO, category: DATAMART, time: Thu
Apr 25 07:54:12 IST 2013, message: Loading periods] (InMemoryNotifier.java
[taskScheduler-5])
* INFO 2013-04-25 07:54:12,101 Number of periods: 2: 0:00:05.942
(Clock.java [taskScheduler-5])
* INFO 2013-04-25 07:54:12,102 [Level: INFO, category: DATAMART, time: Thu
Apr 25 07:54:12 IST 2013, message: Filtering data elements without data]
(InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-25 07:54:14,234 Number of operands with data: 487, Mem
Total in JVM: 622 Free in JVM: 285 Max Limit: 1344: 0:00:08.075 (Clock.java
[taskScheduler-5])
* INFO 2013-04-25 07:54:14,234 [Level: INFO, category: DATAMART, time: Thu
Apr 25 07:54:14 IST 2013, message: Populating crosstabulation table]
(InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-25 07:54:25,438 Crosstab table columns: 489, rows: 0
(DefaultCrossTabService.java [SimpleAsyncTaskExecutor-98])
* INFO 2013-04-25 07:54:26,761 Crosstab table columns: 489, rows: 0
(DefaultCrossTabService.java [SimpleAsyncTaskExecutor-97])
* INFO 2013-04-25 07:54:27,003 Crosstab table columns: 489, rows: 1
(DefaultCrossTabService.java [SimpleAsyncTaskExecutor-100])
* INFO 2013-04-25 07:54:27,027 Crosstab table columns: 489, rows: 1
(DefaultCrossTabService.java [SimpleAsyncTaskExecutor-99])
* INFO 2013-04-25 07:54:27,027 Populated crosstab table, Mem Total in JVM:
624 Free in JVM: 385 Max Limit: 1344: 0:00:20.868 (Clock.java
[taskScheduler-5])
* INFO 2013-04-25 07:54:27,030 Created aggregated data cache, number of
indicator operands: 232, operands with data: 487: 0:00:20.871 (Clock.java
[taskScheduler-5])
* INFO 2013-04-25 07:54:27,039 [Level: INFO, category: DATAMART, time: Thu
Apr 25 07:54:27 IST 2013, message: Exporting data for data element data]
(InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-25 07:54:28,213 Data element export task done
(DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-102])
* ERROR 2013-04-25 07:54:28,663 Unexpected error occurred in scheduled
task. (TaskUtils.java [taskScheduler-5])
java.lang.RuntimeException: Exception during execution
at
org.hisp.dhis.system.util.ConcurrentUtils.waitForCompletion(ConcurrentUtils.java:54)
at
org.hisp.dhis.datamart.engine.DefaultDataMartEngine.export(DefaultDataMartEngine.java:348)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
at
org.amplecode.quick.StatementInterceptor.intercept(StatementInterceptor.java:71)
at sun.reflect.GeneratedMethodAccessor570.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
at
org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy105.export(Unknown Source)
at
org.hisp.dhis.system.scheduling.DataMartTask.run(DataMartTask.java:163)
at
org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:53)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
Caused by: java.util.concurrent.ExecutionException:
java.lang.RuntimeException: Failed to flush BatchHandler
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:252)
at java.util.concurrent.FutureTask.get(FutureTask.java:111)
at
org.hisp.dhis.system.util.ConcurrentUtils.waitForCompletion(ConcurrentUtils.java:50)
... 33 more
Caused by: java.lang.RuntimeException: Failed to flush BatchHandler
at
org.amplecode.quick.batchhandler.AbstractBatchHandler.flush(AbstractBatchHandler.java:311)
at
org.hisp.dhis.datamart.dataelement.DefaultDataElementDataMart.exportDataValues(DefaultDataElementDataMart.java:217)
at sun.reflect.GeneratedMethodAccessor521.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.aop.interceptor.AsyncExecutionInterceptor$1.call(AsyncExecutionInterceptor.java:80)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
... 1 more
Caused by: com.mysql.jdbc.MysqlDataTruncation: Data truncation: Out of
range value for column 'value' at row 96
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4094)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4028)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2677)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1748)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1665)
at
org.amplecode.quick.batchhandler.AbstractBatchHandler.flush(AbstractBatchHandler.java:295)
... 11 more
*Cleared cash.
Archived data values and tried to run the datamart to locate the data
vulues causing the problem. But it still gives the same result.
*
*Once all the existing data archived, Datamart behaves normally.
*
*How to solve this problem (How to visualize already available data) ?
*
*(Tomcat Log with fresh test data attached)*
*Sorry for the earlier post....*
with regards,
Subodha.
* INFO 2013-04-26 05:06:56,835 Login success for user: 'subodha', ip: '175.157.117.217' (DefaultUserAuditService.java [http-8080-6])
* INFO 2013-04-26 05:07:32,307 SELECT COUNT(*) FROM datavaluearchive AS a JOIN datavalue AS d ON (a.dataelementid=d.dataelementid AND a.periodid=d.periodid AND a.sourceid=d.sourceid AND a.categoryoptioncomboid=d.categoryoptioncomboid); (JdbcDataArchiveStore.java [http-8080-6])
* INFO 2013-04-26 05:07:53,758 Archiving: start date: 2010-01-01, end date: 2013-04-26, operation: archive, strategy: oldest (ArchiveDataAction.java [http-8080-6])
* INFO 2013-04-26 05:07:53,759 DELETE d FROM datavalue AS d INNER JOIN datavaluearchive AS a WHERE d.dataelementid=a.dataelementid AND d.periodid=a.periodid AND d.sourceid=a.sourceid AND d.categoryoptioncomboid=a.categoryoptioncomboid AND d.lastupdated<a.lastupdated (JdbcDataArchiveStore.java [http-8080-6])
* INFO 2013-04-26 05:07:53,764 DELETE a FROM datavaluearchive AS a INNER JOIN datavalue AS d WHERE a.dataelementid=d.dataelementid AND a.periodid=d.periodid AND a.sourceid=d.sourceid AND a.categoryoptioncomboid=d.categoryoptioncomboid AND a.lastupdated<=d.lastupdated (JdbcDataArchiveStore.java [http-8080-6])
* INFO 2013-04-26 05:07:53,769 INSERT INTO datavaluearchive ( SELECT d.* FROM datavalue AS d JOIN period AS p ON (d.periodid=p.periodid) WHERE p.startdate>='2010-01-01' AND p.enddate<='2013-04-26' ); (JdbcDataArchiveStore.java [http-8080-6])
* INFO 2013-04-26 05:07:53,898 DELETE d FROM datavalue AS d INNER JOIN period as p WHERE d.periodid=p.periodid AND p.startdate>='2010-01-01' AND p.enddate<='2013-04-26' (JdbcDataArchiveStore.java [http-8080-6])
* INFO 2013-04-26 05:07:54,059 SELECT COUNT(*) as dem FROM datavaluearchive; (JdbcDataArchiveStore.java [http-8080-6])
* WARN 2013-04-26 05:08:34,069 HHH000179: Narrowing proxy to class org.hisp.dhis.period.QuarterlyPeriodType - this operation breaks == (StatefulPersistenceContext.java [http-8080-8])
* WARN 2013-04-26 05:08:41,265 HHH000179: Narrowing proxy to class org.hisp.dhis.period.QuarterlyPeriodType - this operation breaks == (StatefulPersistenceContext.java [http-8080-8])
* WARN 2013-04-26 05:08:42,064 HHH000179: Narrowing proxy to class org.hisp.dhis.period.QuarterlyPeriodType - this operation breaks == (StatefulPersistenceContext.java [http-8080-8])
* WARN 2013-04-26 05:08:51,721 HHH000179: Narrowing proxy to class org.hisp.dhis.period.QuarterlyPeriodType - this operation breaks == (StatefulPersistenceContext.java [http-8080-8])
* WARN 2013-04-26 05:08:53,192 HHH000179: Narrowing proxy to class org.hisp.dhis.period.QuarterlyPeriodType - this operation breaks == (StatefulPersistenceContext.java [http-8080-8])
* WARN 2013-04-26 05:08:54,132 HHH000179: Narrowing proxy to class org.hisp.dhis.period.QuarterlyPeriodType - this operation breaks == (StatefulPersistenceContext.java [http-8080-8])
* WARN 2013-04-26 05:08:57,562 HHH000179: Narrowing proxy to class org.hisp.dhis.period.QuarterlyPeriodType - this operation breaks == (StatefulPersistenceContext.java [http-8080-8])
* INFO 2013-04-26 05:09:38,394 Using periods: [[Monthly: Tue Jan 01 00:00:00 IST 2013 - Thu Jan 31 00:00:00 IST 2013], [Monthly: Fri Feb 01 00:00:00 IST 2013 - Thu Feb 28 00:00:00 IST 2013], [Monthly: Fri Mar 01 00:00:00 IST 2013 - Sun Mar 31 00:00:00 IST 2013], [Monthly: Mon Apr 01 00:00:00 IST 2013 - Tue Apr 30 00:00:00 IST 2013], [Quarterly: Tue Jan 01 00:00:00 IST 2013 - Sun Mar 31 00:00:00 IST 2013], [Quarterly: Mon Apr 01 00:00:00 IST 2013 - Sun Jun 30 00:00:00 IST 2013], [Yearly: Tue Jan 01 00:00:00 IST 2013 - Tue Dec 31 00:00:00 IST 2013], [SixMonthly: Tue Jan 01 00:00:00 IST 2013 - Sun Jun 30 00:00:00 IST 2013]] (DataMartTask.java [taskScheduler-5])
* INFO 2013-04-26 05:09:38,402 Data mart export process started, number of CPU cores: 4, Mem Total in JVM: 774 Free in JVM: 356 Max Limit: 1344: 0:00:00.000 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:38,402 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:38 IST 2013, message: Data mart export process started] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:39,148 Recreated temporary tables: 0:00:00.746 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:39,149 Data elements: 1228, indicators: 294, periods: 8, org units: 1296: 0:00:00.746 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:39,321 Retrieved meta-data objects, using periods: [[Quarterly: 2013-01-01 - 2013-03-31], [Monthly: 2013-01-01 - 2013-01-31], [Yearly: 2013-01-01 - 2013-12-31], [SixMonthly: 2013-01-01 - 2013-06-30], [Monthly: 2013-02-01 - 2013-02-28], [Monthly: 2013-03-01 - 2013-03-31], [Quarterly: 2013-04-01 - 2013-06-30], [Monthly: 2013-04-01 - 2013-04-30]]: 0:00:00.919 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:39,321 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:39 IST 2013, message: Filtering meta-data] (InMemoryNotifier.java [taskScheduler-5])
* WARN 2013-04-26 05:09:39,421 Indicator is invalid: [Number of Dental Surgeons per 10,000 population] (DefaultExpressionService.java [taskScheduler-5])
* INFO 2013-04-26 05:09:39,631 Filtered objects: 0:00:01.229 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:39,632 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:39 IST 2013, message: Loading indicators] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:39,651 Exploded indicator expressions: 0:00:01.249 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:39,651 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:39 IST 2013, message: Loading data elements] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:40,141 Retrieved operands: 1493: 0:00:01.739 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:40,142 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:40 IST 2013, message: Loading periods] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:40,142 Number of periods: 8: 0:00:01.740 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:40,142 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:40 IST 2013, message: Filtering data elements without data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:40,352 Number of operands with data: 6, Mem Total in JVM: 774 Free in JVM: 274 Max Limit: 1344: 0:00:01.950 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:40,352 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:40 IST 2013, message: Populating crosstabulation table] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,002 Crosstab table columns: 8, rows: 0 (DefaultCrossTabService.java [SimpleAsyncTaskExecutor-249])
* INFO 2013-04-26 05:09:42,062 Crosstab table columns: 8, rows: 0 (DefaultCrossTabService.java [SimpleAsyncTaskExecutor-252])
* INFO 2013-04-26 05:09:42,100 Crosstab table columns: 8, rows: 1 (DefaultCrossTabService.java [SimpleAsyncTaskExecutor-251])
* INFO 2013-04-26 05:09:42,111 Crosstab table columns: 8, rows: 0 (DefaultCrossTabService.java [SimpleAsyncTaskExecutor-250])
* INFO 2013-04-26 05:09:42,111 Populated crosstab table, Mem Total in JVM: 759 Free in JVM: 526 Max Limit: 1344: 0:00:03.709 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,112 Created aggregated data cache, number of indicator operands: 4, operands with data: 6: 0:00:03.710 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,113 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:42 IST 2013, message: Exporting data for data element data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,419 Data element export task done (DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-256])
* INFO 2013-04-26 05:09:42,427 Data element export task done (DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-255])
* INFO 2013-04-26 05:09:42,595 Data element export task done (DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-253])
* INFO 2013-04-26 05:09:42,630 Data element export task done (DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-254])
* INFO 2013-04-26 05:09:42,630 Exported values for data element operands (6), pages: 4, Mem Total in JVM: 759 Free in JVM: 501 Max Limit: 1344: 0:00:04.228 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,630 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:42 IST 2013, message: Dropping data element index] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,631 Dropped data element index: 0:00:04.229 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,631 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:42 IST 2013, message: Deleting existing data element data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,633 Deleted existing data element data: 0:00:04.231 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,634 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:42 IST 2013, message: Copying data element data from temporary table] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,636 Copied data element data from temporary table: 0:00:04.234 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,636 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:42 IST 2013, message: Creating data element index] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,637 Created data element index: 0:00:04.235 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,637 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:42 IST 2013, message: Exporting data for indicator data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:42,720 Indicator export task done (DefaultIndicatorDataMart.java [SimpleAsyncTaskExecutor-259])
* INFO 2013-04-26 05:09:45,428 Indicator export task done (DefaultIndicatorDataMart.java [SimpleAsyncTaskExecutor-258])
* INFO 2013-04-26 05:09:45,655 Indicator export task done (DefaultIndicatorDataMart.java [SimpleAsyncTaskExecutor-260])
* INFO 2013-04-26 05:09:48,489 Indicator export task done (DefaultIndicatorDataMart.java [SimpleAsyncTaskExecutor-257])
* INFO 2013-04-26 05:09:48,497 Exported values for indicators (293), pages: 4, Mem Total in JVM: 762 Free in JVM: 345 Max Limit: 1344: 0:00:10.095 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,498 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:48 IST 2013, message: Dropping indicator index] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,533 Dropped indicator index, Mem Total in JVM: 762 Free in JVM: 345 Max Limit: 1344: 0:00:10.131 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,534 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:48 IST 2013, message: Deleting existing indicator data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,542 Deleted existing indicator data: 0:00:10.140 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,567 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:48 IST 2013, message: Copying indicator data from temporary table] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,724 Copied indicator data from temporary table: 0:00:10.322 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,729 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:48 IST 2013, message: Creating indicator index] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,730 Created indicator index: 0:00:10.328 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,730 Aggregated data export done: 0:00:10.328 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,810 Created aggregated org unit data cache: 0:00:10.408 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:48,810 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:48 IST 2013, message: Exporting org unit data element data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,065 Data element export task done (DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-264])
* INFO 2013-04-26 05:09:49,068 Data element export task done (DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-262])
* INFO 2013-04-26 05:09:49,093 Data element export task done (DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-263])
* INFO 2013-04-26 05:09:49,331 Data element export task done (DefaultDataElementDataMart.java [SimpleAsyncTaskExecutor-261])
* INFO 2013-04-26 05:09:49,331 Exported values for data element operands (6), pages: 4, Mem Total in JVM: 762 Free in JVM: 281 Max Limit: 1344: 0:00:10.929 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,332 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:49 IST 2013, message: Dropping data element data indexes] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,332 Dropped org unit data element index: 0:00:10.930 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,332 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:49 IST 2013, message: Deleting existing org unit data element data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,335 Deleted existing aggregated org unit datavalues: 0:00:10.933 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,335 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:49 IST 2013, message: Copying org unit data element data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,338 Copied org unit data element data from temporary table: 0:00:10.935 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,338 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:49 IST 2013, message: Creating org unit data element index] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,338 Created org unit data element index: 0:00:10.936 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,339 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:49 IST 2013, message: Exporting data for org unit indicator data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:49,455 Indicator export task done (DefaultIndicatorDataMart.java [SimpleAsyncTaskExecutor-266])
* INFO 2013-04-26 05:09:49,470 Indicator export task done (DefaultIndicatorDataMart.java [SimpleAsyncTaskExecutor-268])
* INFO 2013-04-26 05:09:49,482 Indicator export task done (DefaultIndicatorDataMart.java [SimpleAsyncTaskExecutor-267])
* INFO 2013-04-26 05:09:55,926 Indicator export task done (DefaultIndicatorDataMart.java [SimpleAsyncTaskExecutor-265])
* INFO 2013-04-26 05:09:55,927 Exported values for indicators (293), pages: 4, Mem Total in JVM: 807 Free in JVM: 248 Max Limit: 1344: 0:00:17.525 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:55,927 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:55 IST 2013, message: Dropping org unit indicator index] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:55,928 Dropped org unit indicator index, Mem Total in JVM: 807 Free in JVM: 248 Max Limit: 1344: 0:00:17.526 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:55,929 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:55 IST 2013, message: Deleting existing org unit indicator data] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:55,936 Deleted existing aggregated org unit indicatorvalues: 0:00:17.534 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:55,936 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:55 IST 2013, message: Copying org unit indicator data from temporary table] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,003 Copied org unit indicator data from temporary table: 0:00:17.601 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,004 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:56 IST 2013, message: Creating org unit indicator indexes] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,004 Created org unit indicator index: 0:00:17.602 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,005 Aggregated org unit data export done: 0:00:17.603 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,194 Dropped crosstab table: 0:00:17.792 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,195 Data mart export process completed: 0:00:17.793 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,195 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:56 IST 2013, message: Data mart process completed] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,221 Data completeness export process started, number of CPU cores: 4, Mem Total in JVM: 807 Free in JVM: 244 Max Limit: 1344: 0:00:00.000 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,221 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:56 IST 2013, message: Completeness export process started] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:56,227 Dropped potential index: 0:00:00.006 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:58,049 Deleted existing completeness data: 0:00:01.827 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:58,049 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:58 IST 2013, message: Exporting completeness for data sets] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:09:58,592 Completeness export task done (AbstractDataSetCompletenessService.java [SimpleAsyncTaskExecutor-270])
* INFO 2013-04-26 05:09:58,602 Completeness export task done (AbstractDataSetCompletenessService.java [SimpleAsyncTaskExecutor-271])
* INFO 2013-04-26 05:09:58,689 Completeness export task done (AbstractDataSetCompletenessService.java [SimpleAsyncTaskExecutor-272])
* INFO 2013-04-26 05:09:58,896 Completeness export task done (AbstractDataSetCompletenessService.java [SimpleAsyncTaskExecutor-269])
* INFO 2013-04-26 05:09:58,908 Created index: 0:00:02.687 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:58,908 Completeness export process completed: 0:00:02.687 (Clock.java [taskScheduler-5])
* INFO 2013-04-26 05:09:58,909 [Level: INFO, category: DATAMART, time: Fri Apr 26 05:09:58 IST 2013, message: Completeness process completed] (InMemoryNotifier.java [taskScheduler-5])
* INFO 2013-04-26 05:12:03,701 'subodha' edited OrganisationUnit 'TH-Kurunegala' (DefaultOrganisationUnitService.java [http-8080-8])
* INFO 2013-04-26 05:12:25,779 'subodha' edited OrganisationUnit 'TH-Kurunegala' (DefaultOrganisationUnitService.java [http-8080-8])
