dhis2-devs team mailing list archive

[Seid Hussein <seid.hisp@xxxxxxxxx>]

Hi all,

We have been facing a problem these days where we are trying to run the
DHIS2 database locally even though it is working without a problem on our
Amazon EC2 server.

Whenever tomcat starts, it immediately goes to running analytics and we can
not get in to any of the modules since it hangs up on that specific task.
It hangs on like that for hours. This happens even if we have stopped the
datamart and analytics schedule.

I check my JAVA_OPTS and we have

-Xmx4000m -Xms2000m -XX:MaxPermSize=500m -XX:PermSize=300m

which should be more than enough.

I have a 6GB RAM Windows 8.1 machine, with the latest java build.


All the best,


Seid,

2014-07-10 15:22:20 Commons Daemon procrun stdout initialized
* INFO  2014-07-10 15:23:11,104 System property dhis2.home not set (DefaultLocationManager.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:11,108 Environment variable DHIS2_HOME points to C:\Users\seid\dhis2 (DefaultLocationManager.java [localhost-startStop-1])
* WARN  2014-07-10 15:23:12,247 HHH000223: Recognized obsolete hibernate namespace http://hibernate.sourceforge.net/. Use namespace http://www.hibernate.org/dtd/ instead. Refer to Hibernate 3.6 Migration Guide! (DTDEntityResolver.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:14,238 Hibernate configuration loaded, using dialect: org.hibernate.dialect.PostgreSQLDialect (DefaultHibernateConfigurationProvider.java [localhost-startStop-1])
* WARN  2014-07-10 15:23:15,800 HHH000223: Recognized obsolete hibernate namespace http://hibernate.sourceforge.net/. Use namespace http://www.hibernate.org/dtd/ instead. Refer to Hibernate 3.6 Migration Guide! (DTDEntityResolver.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:36,202 Found the following message senders: [org.hisp.dhis.message.EmailMessageSender@2a5967a4, org.hisp.dhis.sms.SmsMessageSender@53a355b4] (DefaultMessageService.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:42,345 Detecting apps: [] (DefaultAppManager.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:42,456 SMSLib: A Java API library for sending and receiving SMS via a GSM modem or other supported gateways.
This software is distributed under the terms of the Apache v2.0 License.
Web Site: http://smslib.org (Service.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:42,456 Version: 3.5.3 (Service.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:42,457 JRE Version: 1.7.0_55 (Service.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:42,457 JRE Impl Version: 24.55-b03 (Service.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:42,457 O/S: Windows 8 / amd64 / 6.2 (Service.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:46,574 Executing startup routine [1 of 11, runlevel 1]: TableAlteror (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:56,306 Tables updated (TableAlteror.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:56,307 Executing startup routine [2 of 11, runlevel 1]: MapViewUpgrader (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:56,582 Executing startup routine [3 of 11, runlevel 2]: IdentityPopulator (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:57,683 Executing startup routine [4 of 11, runlevel 2]: PeriodTypePopulator (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:57,692 Executing startup routine [5 of 11, runlevel 3]: TableCreator (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:57,720 Executing startup routine [6 of 11, runlevel 3]: DataElementDefaultDimensionPopulator (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:58,003 Linked default category with default concept (DataElementDefaultDimensionPopulator.java [localhost-startStop-1])
* INFO  2014-07-10 15:23:58,496 Executing startup routine [7 of 11, runlevel 4]: PatientTableAlteror (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:24:01,425 Executing startup routine [8 of 11, runlevel 5]: DataEntryFormUpgrader (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:24:01,459 Upgraded custom case entry form identifiers: 21 (DataEntryFormUpgrader.java [localhost-startStop-1])
* INFO  2014-07-10 15:24:01,463 Executing startup routine [9 of 11, runlevel 6]: ExpressionUpgrader (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:24:01,568 Executing startup routine [10 of 11, runlevel 7]: ConfigurationPopulator (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:24:01,577 Executing startup routine [11 of 11, runlevel 7]: I18nLocalePopulator (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:24:01,588 All startup routines done (DefaultStartupRoutineExecutor.java [localhost-startStop-1])
* INFO  2014-07-10 15:24:23,071 Login success for user: 'admin', ip: '127.0.0.1' (DefaultUserAuditService.java [http-apr-8090-exec-5])
* INFO  2014-07-10 15:24:26,327 Time: 64933 micros: Planned query, got: 3 for optimal: 4 (Timer.java [http-apr-8090-exec-8])
* INFO  2014-07-10 15:24:26,330 Time: 57394 micros: Planned query, got: 4 for optimal: 4 (Timer.java [http-apr-8090-exec-6])
* INFO  2014-07-10 15:24:26,371 Time: 68661 micros: Planned query, got: 3 for optimal: 4 (Timer.java [http-apr-8090-exec-2])
* INFO  2014-07-10 15:24:26,506 Time: 156824 micros: Planned query, got: 3 for optimal: 4 (Timer.java [http-apr-8090-exec-10])
* INFO  2014-07-10 15:24:26,563 Time: 69779 micros: Planned query, got: 4 for optimal: 4 (Timer.java [http-apr-8090-exec-7])
* INFO  2014-07-10 15:24:26,810 Time: 81369 micros: Planned query, got: 4 for optimal: 4 (Timer.java [http-apr-8090-exec-5])
* INFO  2014-07-10 15:24:27,692 Time: 1347519 micros: Analytics SQL: select "ds","uidlevel3", count(value) as value from completeness_2013 where "ds" in ('bWhkNjy0tWV') and "uidlevel3" in ('aEvBywGwJ9Z') and ("quarterly" in ('2013Q4')) group by "ds","uidlevel3" (Timer.java [SimpleAsyncTaskExecutor-7])
* INFO  2014-07-10 15:24:27,715 Time: 1368579 micros: Analytics SQL: select "ds","uidlevel3", count(value) as value from completeness_2013 where "ds" in ('bWhkNjy0tWV') and "uidlevel3" in ('nDDNPxVCCV6', 'oBQAH0qp0kG', 'qvgZuaxDlJm', 'CruuKZTKTfb') and ("quarterly" in ('2013Q4')) group by "ds","uidlevel3" (Timer.java [SimpleAsyncTaskExecutor-6])
* INFO  2014-07-10 15:24:27,780 Time: 1434924 micros: Analytics SQL: select "ds","uidlevel3", count(value) as value from completeness_2013 where "ds" in ('bWhkNjy0tWV') and "uidlevel3" in ('eli8FbaNLOo', 'NGuJaOX19zs', 'BNwe9N0tTDL', 'Uf2DA8mC0ie') and ("quarterly" in ('2013Q4')) group by "ds","uidlevel3" (Timer.java [SimpleAsyncTaskExecutor-4])
* INFO  2014-07-10 15:24:27,780 Time: 1434255 micros: Analytics SQL: select "ds","uidlevel3", count(value) as value from completeness_2013 where "ds" in ('bWhkNjy0tWV') and "uidlevel3" in ('tFxuOmRMm5k', 'QA8zyEfKzfC', 'JEU953zMVuS', 'P4zQ2Caz6zP') and ("quarterly" in ('2013Q4')) group by "ds","uidlevel3" (Timer.java [SimpleAsyncTaskExecutor-5])
* INFO  2014-07-10 15:24:27,781 Time: 1508779 micros: Got aggregated values for query group (Timer.java [http-apr-8090-exec-6])
* INFO  2014-07-10 15:24:27,782 Time: 1509241 micros: Got aggregated values (Timer.java [http-apr-8090-exec-6])
* INFO  2014-07-10 15:24:27,783 Time: 213 micros: Planned query, got: 4 for optimal: 4 (Timer.java [http-apr-8090-exec-6])
* INFO  2014-07-10 15:24:30,359 Time: 2573705 micros: Analytics SQL: select "ds","uidlevel3", count(value) as value from completenesstarget where "ds" in ('bWhkNjy0tWV') and "uidlevel3" in ('aEvBywGwJ9Z') group by "ds","uidlevel3" (Timer.java [SimpleAsyncTaskExecutor-25])
* INFO  2014-07-10 15:24:31,232 Time: 4662696 micros: Analytics SQL: select "sixmonthly","de","co", sum(value) as value from analytics_2013 where "sixmonthly" in ('2013S2') and "de" in ('Mzdlf76VBcT') and ("uidlevel1" in ('okciEipKKuv')) group by "sixmonthly","de","co" (Timer.java [SimpleAsyncTaskExecutor-17])
* INFO  2014-07-10 15:24:31,232 Time: 4666504 micros: Analytics SQL: select "sixmonthly","de","co", sum(value) as value from analytics_2013 where "sixmonthly" in ('2013S2') and "de" in ('qZ6YqQOfAbc') and ("uidlevel1" in ('okciEipKKuv')) group by "sixmonthly","de","co" (Timer.java [SimpleAsyncTaskExecutor-14])
* INFO  2014-07-10 15:24:31,295 Time: 4955238 micros: Analytics SQL: select "uidlevel1","de","co", sum(value) as value from analytics_2013 where "uidlevel1" in ('okciEipKKuv') and "de" in ('mc2SFNBbjfS', 'QH7em8EGueG', 'KKrpVlQgpto') and ("sixmonthly" in ('2013S2')) group by "uidlevel1","de","co" (Timer.java [SimpleAsyncTaskExecutor-1])
* INFO  2014-07-10 15:24:31,295 Time: 4949749 micros: Analytics SQL: select "uidlevel1","de","co", sum(value) as value from analytics_2013 where "uidlevel1" in ('okciEipKKuv') and "de" in ('lQahl6GuMqc', 'iQAFCu54fh9', 'wA4P6V8tD1T') and ("sixmonthly" in ('2013S2')) group by "uidlevel1","de","co" (Timer.java [SimpleAsyncTaskExecutor-2])
* INFO  2014-07-10 15:24:31,300 Time: 4731868 micros: Analytics SQL: select "sixmonthly","de","co", sum(value) as value from analytics_2013 where "sixmonthly" in ('2013S2') and "de" in ('x4J3FZppDqi') and ("uidlevel1" in ('okciEipKKuv')) group by "sixmonthly","de","co" (Timer.java [SimpleAsyncTaskExecutor-15])
* INFO  2014-07-10 15:24:31,305 Time: 4965946 micros: Analytics SQL: select "uidlevel1","de","co", sum(value) as value from analytics_2013 where "uidlevel1" in ('okciEipKKuv') and "de" in ('Os4jLzcxOdp', 'lPPt4ttckqY', 'vosd5rcdU5l') and ("sixmonthly" in ('2013S2')) group by "uidlevel1","de","co" (Timer.java [SimpleAsyncTaskExecutor-3])
* INFO  2014-07-10 15:24:31,306 Time: 5044370 micros: Got aggregated values for query group (Timer.java [http-apr-8090-exec-8])
* INFO  2014-07-10 15:24:31,307 Time: 5045587 micros: Got aggregated values (Timer.java [http-apr-8090-exec-8])
* INFO  2014-07-10 15:24:31,310 Time: 4739475 micros: Analytics SQL: select "sixmonthly","de","co", sum(value) as value from analytics_2013 where "sixmonthly" in ('2013S2') and "de" in ('IfNKtgXFCgc') and ("uidlevel1" in ('okciEipKKuv')) group by "sixmonthly","de","co" (Timer.java [SimpleAsyncTaskExecutor-16])
* INFO  2014-07-10 15:24:31,312 Time: 4818422 micros: Got aggregated values for query group (Timer.java [http-apr-8090-exec-7])
* INFO  2014-07-10 15:24:31,312 Time: 4819250 micros: Got aggregated values (Timer.java [http-apr-8090-exec-7])
* INFO  2014-07-10 15:24:31,373 Time: 3587693 micros: Analytics SQL: select "ds","uidlevel3", count(value) as value from completenesstarget where "ds" in ('bWhkNjy0tWV') and "uidlevel3" in ('nDDNPxVCCV6', 'oBQAH0qp0kG', 'qvgZuaxDlJm', 'CruuKZTKTfb') group by "ds","uidlevel3" (Timer.java [SimpleAsyncTaskExecutor-24])
* INFO  2014-07-10 15:24:31,373 Time: 3587743 micros: Analytics SQL: select "ds","uidlevel3", count(value) as value from completenesstarget where "ds" in ('bWhkNjy0tWV') and "uidlevel3" in ('eli8FbaNLOo', 'NGuJaOX19zs', 'BNwe9N0tTDL', 'Uf2DA8mC0ie') group by "ds","uidlevel3" (Timer.java [SimpleAsyncTaskExecutor-22])
* INFO  2014-07-10 15:24:31,375 Time: 3590165 micros: Analytics SQL: select "ds","uidlevel3", count(value) as value from completenesstarget where "ds" in ('bWhkNjy0tWV') and "uidlevel3" in ('tFxuOmRMm5k', 'QA8zyEfKzfC', 'JEU953zMVuS', 'P4zQ2Caz6zP') group by "ds","uidlevel3" (Timer.java [SimpleAsyncTaskExecutor-23])
* INFO  2014-07-10 15:24:31,375 Time: 3591584 micros: Got aggregated values for query group (Timer.java [http-apr-8090-exec-6])
* INFO  2014-07-10 15:24:31,376 Time: 3592009 micros: Got aggregated values (Timer.java [http-apr-8090-exec-6])
* INFO  2014-07-10 15:24:31,903 Time: 5395169 micros: Analytics SQL: select "de","uidlevel2","co", sum(value) as value from analytics_2014 where "de" in ('SbgSFPYNiwM', 'bLTq16CvDiR', 'KzClX0jQpjp') and "uidlevel2" in ('JwbrLfNyl2Z', 'veFqNdvlo2D', 'SGNwrDSnvu7', 'Bgj4h25rV0p') and ("quarterly" in ('2014Q1')) group by "de","uidlevel2","co" (Timer.java [SimpleAsyncTaskExecutor-11])
* INFO  2014-07-10 15:24:32,528 Time: 6019310 micros: Analytics SQL: select "de","uidlevel2","co", sum(value) as value from analytics_2014 where "de" in ('rE69DXK98bT', 'L8ySZGIxhAl', 'RhFY2MBcT8i') and "uidlevel2" in ('JwbrLfNyl2Z', 'veFqNdvlo2D', 'SGNwrDSnvu7', 'Bgj4h25rV0p') and ("quarterly" in ('2014Q1')) group by "de","uidlevel2","co" (Timer.java [SimpleAsyncTaskExecutor-13])
* INFO  2014-07-10 15:24:32,590 Time: 6080145 micros: Analytics SQL: select "de","uidlevel2","co", sum(value) as value from analytics_2014 where "de" in ('sLwpv1UT6sd', 'RfpmWBwwaY5', 'LF2FZF8t0j1') and "uidlevel2" in ('JwbrLfNyl2Z', 'veFqNdvlo2D', 'SGNwrDSnvu7', 'Bgj4h25rV0p') and ("quarterly" in ('2014Q1')) group by "de","uidlevel2","co" (Timer.java [SimpleAsyncTaskExecutor-12])
* INFO  2014-07-10 15:24:32,591 Time: 6241281 micros: Got aggregated values for query group (Timer.java [http-apr-8090-exec-10])
* INFO  2014-07-10 15:24:32,592 Time: 6242712 micros: Got aggregated values (Timer.java [http-apr-8090-exec-10])
* INFO  2014-07-10 15:24:42,180 Time: 15807396 micros: Analytics SQL: select "de","quarterly","co", sum(value) as value from analytics_2014 where "de" in ('UOGBI06CXV6', 'y7UAY5CYBkg', 'B5ROpUORnTH') and "quarterly" in ('2014Q1', '2014Q2') and ("uidlevel1" in ('okciEipKKuv')) group by "de","quarterly","co" (Timer.java [SimpleAsyncTaskExecutor-10])
* INFO  2014-07-10 15:24:42,184 Time: 15368885 micros: Analytics SQL: select "de","quarterly","co", sum(value) as value from analytics_2014 where "de" in ('TkgJ61btnsW') and "quarterly" in ('2014Q1', '2014Q2') and ("uidlevel1" in ('okciEipKKuv')) group by "de","quarterly","co" (Timer.java [SimpleAsyncTaskExecutor-21])
* INFO  2014-07-10 15:24:42,180 Time: 15368032 micros: Analytics SQL: select "de","quarterly","co", sum(value) as value from analytics_2014 where "de" in ('FEqF6ihZfvC', 'rG5dGlxxNLq', 'dDmbJ477qkI', 'Bi6Txvriq7J') and "quarterly" in ('2014Q1', '2014Q2') and ("uidlevel1" in ('okciEipKKuv')) group by "de","quarterly","co" (Timer.java [SimpleAsyncTaskExecutor-19])
* INFO  2014-07-10 15:24:42,180 Time: 15365490 micros: Analytics SQL: select "de","quarterly","co", sum(value) as value from analytics_2014 where "de" in ('iQAFCu54fh9', 'wq9Ag3QZNuV', 'zuK0V2FGgVp', 'MPDpPdKsVYf') and "quarterly" in ('2014Q1', '2014Q2') and ("uidlevel1" in ('okciEipKKuv')) group by "de","quarterly","co" (Timer.java [SimpleAsyncTaskExecutor-20])
* INFO  2014-07-10 15:24:42,188 Time: 15815941 micros: Analytics SQL: select "de","quarterly","co", sum(value) as value from analytics_2014 where "de" in ('lRBU2B7NCAw', 'gqJ9P2JSHMt', 'gzK3PJSsBDU') and "quarterly" in ('2014Q1', '2014Q2') and ("uidlevel1" in ('okciEipKKuv')) group by "de","quarterly","co" (Timer.java [SimpleAsyncTaskExecutor-8])
* INFO  2014-07-10 15:24:42,188 Time: 15376132 micros: Analytics SQL: select "de","quarterly","co", sum(value) as value from analytics_2014 where "de" in ('mc2SFNBbjfS', 'KKrpVlQgpto', 'QH7em8EGueG', 'sNa4rEi1U3p') and "quarterly" in ('2014Q1', '2014Q2') and ("uidlevel1" in ('okciEipKKuv')) group by "de","quarterly","co" (Timer.java [SimpleAsyncTaskExecutor-18])
* INFO  2014-07-10 15:24:42,188 Time: 15815954 micros: Analytics SQL: select "de","quarterly","co", sum(value) as value from analytics_2014 where "de" in ('eGoqhn46mFF', 'zlD93upgsJT', 'Lf4eVORVpjx') and "quarterly" in ('2014Q1', '2014Q2') and ("uidlevel1" in ('okciEipKKuv')) group by "de","quarterly","co" (Timer.java [SimpleAsyncTaskExecutor-9])
* INFO  2014-07-10 15:24:42,189 Time: 15460577 micros: Got aggregated values for query group (Timer.java [http-apr-8090-exec-5])
* INFO  2014-07-10 15:24:42,189 Time: 15886585 micros: Got aggregated values for query group (Timer.java [http-apr-8090-exec-2])
* INFO  2014-07-10 15:24:42,190 Time: 15461134 micros: Got aggregated values (Timer.java [http-apr-8090-exec-5])
* INFO  2014-07-10 15:24:42,190 Time: 15887495 micros: Got aggregated values (Timer.java [http-apr-8090-exec-2])