Hello
With my new lxd installation, when I manually run the analytics, it takes a long time, it seems that it does not work.
There is no error on the web console or in the logs (/opt/dhis2/logs/dhis-analytics-table.log)
Regards
Please post the contents of the Tomcat log file (catalina.out). From the analytics start is fine. You can post it on pastebin.com and paste the link here. You might also want to check the PostgreSQL log file.
Thanks!
1 Like
Hello @Edward_Robinson thank you for your response.
Here is dhis 2 log (sudo dhis2-logview -f hmis)
Aug 09 13:10:05 hmis tomcat9[278]: Server startup in [34,101] milliseconds
Aug 09 13:10:12 hmis tomcat9[278]: * INFO 2021-08-09T13:10:12,237 Login attempt: didate (TwoFactorAuthenticationProvider.java [tomcat-http-2])
Aug 09 13:10:12 hmis tomcat9[278]: * INFO 2021-08-09T13:10:12,475 'system-process' update org.hisp.dhis.user.UserCredentials, name: Mamadou Lamarana DIALLO, uid: PS0ItfXzrpC (AuditLogUtil.java [tomcat-http-2])
Aug 09 13:10:12 hmis tomcat9[278]: * WARN 2021-08-09T13:10:12,481 Authentication event: AuthenticationSuccessEvent; username: didate; ip: 10.13.52.254; sessionId: a900dde4d1c55385d8adfbd719529368659326c8659f27572c4fbcf102faf69e; (AuthenticationLoggerListener.java [tomcat-http-2])
Aug 09 13:10:12 hmis tomcat9[278]: * INFO 2021-08-09T13:10:12,487 'didate' update org.hisp.dhis.user.UserCredentials, name: Mamadou Lamarana DIALLO, uid: PS0ItfXzrpC (AuditLogUtil.java [tomcat-http-2])
Aug 09 13:12:35 hmis tomcat9[278]: * INFO 2021-08-09T13:12:35,113 Scheduler initiated execution of job: JobConfiguration{uid='AAZeWSVIWSQ', name='inMemoryAnalyticsJob', jobType=ANALYTICS_TABLE, cronExpression='', delay='null', jobParameters=org.hisp.dhis.scheduling.parameters.AnalyticsJobParameters@17bc019, enabled=true, inMemoryJob=true, lastRuntimeExecution='null', userUid='SCqaDylGxFt', leaderOnlyJob=false, jobStatus=SCHEDULED, nextExecutionTime=null, lastExecutedStatus=NOT_STARTED, lastExecuted=null} (DefaultSchedulingManager.java [tomcat-http-5])
Aug 09 13:12:35 hmis tomcat9[278]: * INFO 2021-08-09T13:12:35,123 Found 7 analytics table types: [COMPLETENESS_TARGET, DATA_VALUE, ENROLLMENT, COMPLETENESS, VALIDATION_RESULT, ORG_UNIT_TARGET, EVENT] (DefaultAnalyticsTableGenerator.java [taskScheduler-24])
Aug 09 13:12:35 hmis tomcat9[278]: * INFO 2021-08-09T13:12:35,125 Analytics table update: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], start time=2021-08-09T13:12:35} (DefaultAnalyticsTableGenerator.java [taskScheduler-24])
Aug 09 13:12:35 hmis tomcat9[278]: * INFO 2021-08-09T13:12:35,125 Last successful analytics table update: '2021-08-09T02:00:00' (DefaultAnalyticsTableGenerator.java [taskScheduler-24])
Aug 09 13:12:35 hmis tomcat9[278]: * INFO 2021-08-09T13:12:35,126 [Level: INFO, category: ANALYTICS_TABLE, time: Mon Aug 09 13:12:35 UTC 2021, message: Analytics table update process started] (InMemoryNotifier.java [taskScheduler-24])
Aug 09 13:12:35 hmis tomcat9[278]: * INFO 2021-08-09T13:12:35,127 [Level: INFO, category: ANALYTICS_TABLE, time: Mon Aug 09 13:12:35 UTC 2021, message: Updating resource tables] (InMemoryNotifier.java [taskScheduler-24])
Aug 09 13:12:35 hmis tomcat9[278]: * INFO 2021-08-09T13:12:35,142 Generating resource table: '_orgunitstructure' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:36 hmis tomcat9[278]: * INFO 2021-08-09T13:12:36,483 Resource table '_orgunitstructure' update done: '00:00:01.338' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:36 hmis tomcat9[278]: * INFO 2021-08-09T13:12:36,535 Generating resource table: '_datasetorganisationunitcategory' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:36 hmis tomcat9[278]: * INFO 2021-08-09T13:12:36,959 Resource table '_datasetorganisationunitcategory' update done: '00:00:00.423' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:36 hmis tomcat9[278]: * INFO 2021-08-09T13:12:36,996 Generating resource table: '_categoryoptioncomboname' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,027 Resource table '_categoryoptioncomboname' update done: '00:00:00.030' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,039 Generating resource table: '_dataelementgroupsetstructure' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,054 Resource table '_dataelementgroupsetstructure' update done: '00:00:00.014' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,068 Generating resource table: '_indicatorgroupsetstructure' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,075 Resource table '_indicatorgroupsetstructure' update done: '00:00:00.007' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,086 Generating resource table: '_organisationunitgroupsetstructure' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,504 Resource table '_organisationunitgroupsetstructure' update done: '00:00:00.417' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,519 Generating resource table: '_categorystructure' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,530 Resource table '_categorystructure' update done: '00:00:00.010' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:37 hmis tomcat9[278]: * INFO 2021-08-09T13:12:37,613 Generating resource table: '_dataelementstructure' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:38 hmis tomcat9[278]: * INFO 2021-08-09T13:12:38,746 Resource table '_dataelementstructure' update done: '00:00:01.132' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:38 hmis tomcat9[278]: * INFO 2021-08-09T13:12:38,821 Generating resource table: '_periodstructure' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:39 hmis tomcat9[278]: * INFO 2021-08-09T13:12:39,188 Resource table '_periodstructure' update done: '00:00:00.366' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:39 hmis tomcat9[278]: * INFO 2021-08-09T13:12:39,203 Generating resource table: '_dateperiodstructure' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:43 hmis tomcat9[278]: * INFO 2021-08-09T13:12:43,967 Resource table '_dateperiodstructure' update done: '00:00:04.763' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:43 hmis tomcat9[278]: * INFO 2021-08-09T13:12:43,968 Generating resource table: '_dataelementcategoryoptioncombo' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:43 hmis tomcat9[278]: * INFO 2021-08-09T13:12:43,995 Resource table '_dataelementcategoryoptioncombo' update done: '00:00:00.025' (JdbcResourceTableStore.java [taskScheduler-24])
Aug 09 13:12:44 hmis tomcat9[278]: * INFO 2021-08-09T13:12:44,007 [Level: INFO, category: ANALYTICS_TABLE, time: Mon Aug 09 13:12:44 UTC 2021, message: Updating tables: DATA_VALUE] (InMemoryNotifier.java [taskScheduler-24])
Aug 09 13:12:44 hmis tomcat9[278]: * INFO 2021-08-09T13:12:44,008 Analytics table update parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], start time=2021-08-09T13:12:35} (DefaultAnalyticsTableService.java [taskScheduler-24])
Aug 09 13:12:44 hmis tomcat9[278]: * INFO 2021-08-09T13:12:44,008 Starting update of type: DATA_VALUE, table name: 'analytics', processes: 23: 00:00:00.000 (Clock.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,854 Table update start: analytics, earliest: null, parameters: AnalyticsTableUpdateParams{last years=null, skip resource tables=false, skip table types=[], start time=2021-08-09T13:12:35}: 00:00:02.845 (Clock.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,854 [Level: INFO, category: ANALYTICS_TABLE, time: Mon Aug 09 13:12:46 UTC 2021, message: Performing pre-create table work] (InMemoryNotifier.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,856 Performed pre-create table work: 00:00:02.847 (Clock.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,856 [Level: INFO, category: ANALYTICS_TABLE, time: Mon Aug 09 13:12:46 UTC 2021, message: Dropping temp tables] (InMemoryNotifier.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,857 Dropped temp tables: 00:00:02.848 (Clock.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,857 [Level: INFO, category: ANALYTICS_TABLE, time: Mon Aug 09 13:12:46 UTC 2021, message: Creating analytics tables] (InMemoryNotifier.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,858 Creating table: analytics_temp, columns: 41 (AbstractJdbcTableManager.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,863 Creating partition table: analytics_temp_2016 (AbstractJdbcTableManager.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,866 Creating partition table: analytics_temp_2017 (AbstractJdbcTableManager.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,868 Creating partition table: analytics_temp_2018 (AbstractJdbcTableManager.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,871 Creating partition table: analytics_temp_2019 (AbstractJdbcTableManager.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,874 Creating partition table: analytics_temp_2020 (AbstractJdbcTableManager.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,877 Creating partition table: analytics_temp_2021 (AbstractJdbcTableManager.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,879 Created analytics tables: 00:00:02.871 (Clock.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,880 [Level: INFO, category: ANALYTICS_TABLE, time: Mon Aug 09 13:12:46 UTC 2021, message: Populating analytics tables] (InMemoryNotifier.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,881 Populate table task number: 6 (DefaultAnalyticsTableService.java [taskScheduler-24])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,935 Populate analytics_temp_2016 [INTEGER, INTEGER_POSITIVE, INTEGER_NEGATIVE, INTEGER_ZERO_OR_POSITIVE, NUMBER, UNIT_INTERVAL, PERCENTAGE] in: 0.037828 sec. (AbstractJdbcTableManager.java [taskScheduler-2])
Aug 09 13:12:46 hmis tomcat9[278]: * INFO 2021-08-09T13:12:46,962 Populate analytics_temp_2016 [BOOLEAN, TRUE_ONLY] in: 0.017750 sec. (AbstractJdbcTableManager.java [taskScheduler-2])
Aug 09 13:12:47 hmis tomcat9[278]: * INFO 2021-08-09T13:12:47,005 Populate analytics_temp_2016 [BOOLEAN] in: 0.033170 sec. (AbstractJdbcTableManager.java [taskScheduler-2])
Aug 09 13:12:47 hmis tomcat9[278]: * INFO 2021-08-09T13:12:47,567 Populate analytics_temp_2016 [TEXT, LONG_TEXT, LETTER, TIME, USERNAME, EMAIL, PHONE_NUMBER, URL, DATE, DATETIME, AGE] in: 0.550742 sec. (AbstractJdbcTableManager.java [taskScheduler-2])
Postgres log
root@postgres:~# tail -f /var/log/postgresql/postgresql-13-main.log
;
2021-08-09 13:09:25.718 AFRICA [193335] hmis@hmis ERROR: canceling statement due to user request
2021-08-09 13:09:25.718 AFRICA [193335] hmis@hmis STATEMENT: insert into analytics_temp_2021 ("id","YdWQi4esNNH","ZQxNNHhvlRy","xdJocAtT9PV","tjWaruPEEUI","yeElO1bH2d7","wXNLcs4ZAXp","uidlevel1","uidlevel2","uidlevel3","uidlevel4","uidlevel5","uidlevel6","daily","weekly","weeklywednesday","weeklythursday","weeklysaturday","weeklysunday","biweekly","monthly","bimonthly","quarterly","sixmonthly","sixmonthlyapril","sixmonthlynov","yearly","financialapril","financialjuly","financialoct","financialnov","approvallevel","dx","co","ao","pestartdate","peenddate","year","pe","ou","level","daysxvalue","daysno","value","textvalue") select (de.uid || '-' || ps.iso || '-' || ou.uid || '-' || co.uid || '-' || ao.uid) as id ,ougs."YdWQi4esNNH",ougs."ZQxNNHhvlRy",ougs."xdJocAtT9PV",dcs."tjWaruPEEUI",dcs."yeElO1bH2d7",dcs."wXNLcs4ZAXp",ous."uidlevel1",ous."uidlevel2",ous."uidlevel3",ous."uidlevel4",ous."uidlevel5",ous."uidlevel6",ps."daily",ps."weekly",ps."weeklywednesday",ps."weeklythursday",ps."weeklysaturday",ps."weeklysunday",ps."biweekly",ps."monthly",ps."bimonthly",ps."quarterly",ps."sixmonthly",ps."sixmonthlyapril",ps."sixmonthlynov",ps."yearly",ps."financialapril",ps."financialjuly",ps."financialoct",ps."financialnov",0 as approvallevel,de.uid,co.uid,ao.uid,pe.startdate,pe.enddate,ps.year,ps.iso,ou.uid,ous.level,cast(dv.value as double precision) * ps.daysno as daysxvalue, ps.daysno as daysno, cast(dv.value as double precision) as value, null as textvalue from datavalue dv inner join period pe on dv.periodid=pe.periodid inner join _periodstructure ps on dv.periodid=ps.periodid inner join dataelement de on dv.dataelementid=de.dataelementid inner join _dataelementstructure des on dv.dataelementid = des.dataelementid inner join _dataelementgroupsetstructure degs on dv.dataelementid=degs.dataelementid inner join organisationunit ou on dv.sourceid=ou.organisationunitid left join _orgunitstructure ous on dv.sourceid=ous.organisationunitid inner join _organisationunitgroupsetstructure ougs on dv.sourceid=ougs.organisationunitid and (cast(date_trunc('month', pe.startdate) as date)=ougs.startdate or ougs.startdate is null) inner join categoryoptioncombo co on dv.categoryoptioncomboid=co.categoryoptioncomboid inner join categoryoptioncombo ao on dv.attributeoptioncomboid=ao.categoryoptioncomboid inner join _categorystructure dcs on dv.categoryoptioncomboid=dcs.categoryoptioncomboid inner join _categorystructure acs on dv.attributeoptioncomboid=acs.categoryoptioncomboid inner join _categoryoptioncomboname aon on dv.attributeoptioncomboid=aon.categoryoptioncomboid inner join _categoryoptioncomboname con on dv.categoryoptioncomboid=con.categoryoptioncomboid where de.valuetype in ('INTEGER', 'INTEGER_POSITIVE', 'INTEGER_NEGATIVE', 'INTEGER_ZERO_OR_POSITIVE', 'NUMBER', 'UNIT_INTERVAL', 'PERCENTAGE') and de.domaintype = 'AGGREGATE' and ps.year = 2021 and dv.lastupdated < '2021-08-09T12:24:38' and dv.value is not null and dv.deleted is false and (dv.value != '0' or de.aggregationtype in ('AVERAGE,AVERAGE_SUM_ORG_UNIT')) and dv.value ~* '^(-?[0-9]+)(\.[0-9]+)?$'
2021-08-09 13:09:25.720 AFRICA [193331] hmis@hmis LOG: duration: 564545.057 ms execute <unnamed>/C_17: drop table _orgunitstructure
2021-08-09 13:09:25.721 AFRICA [195047] hmis@hmis LOG: duration: 839785.165 ms execute <unnamed>: drop table if exists analytics_temp cascade
2021-08-09 13:09:25.723 AFRICA [193332] hmis@hmis LOG: duration: 488159.369 ms execute <unnamed>: drop table if exists analytics_temp cascade
2021-08-09 13:09:25.727 AFRICA [193331] hmis@hmis ERROR: canceling statement due to user request
2021-08-09 13:09:25.727 AFRICA [193331] hmis@hmis STATEMENT: analyze _orgunitstructure
2021-08-09 13:09:48.242 AFRICA [196470] hmis@hmis ERROR: extension "postgis" already exists
2021-08-09 13:09:48.242 AFRICA [196470] hmis@hmis STATEMENT: create extension postgis
Could the problem be due to the amount of data (I’m using 2.33) ?
Hello, so according to my observation the problem appears when I try to create an aggregated data form.
When I create the elements below the analytics doesn’t work anymore, when I delete them the analytics works.
The problem is that there is no real error message in the logs.
I even migrated the version of dhis 2 to 2.36 but the same problem occurs again.
Need Help
Hi @didate really sorry for dropping the ball on this, I had eye surgery and forgot about this request.
Is this a small / dummy data set perhaps? I was wondering if you could try sharing the metadata or a database backup with me at erobinson@projectbalance.com
I could take a look after hours.
1 Like
Hello @Edward_Robinson ,
No problem.
the database is a bit heavy so it will be hard to share by email. Is it possible when you have time to check together on my test server?
1 Like
@didate, I asked and it seems this will need the support of the @dhis2-backend team. Would you try to reproduce this issue on one of the play.dhis2.org instances? And please write the steps to reproduce this issue as it’s recommended that you create a Jira issue. 
Thanks!
Hello @Gassim
it works well in dhis 2 play (2.36). I think it’s not a dhis 2 bug, but rather my instance which is a problem. But at the moment I can’t figure out what it is exactly.
To be more precise, the problem appears when I create the category combination.
Here are the creation steps that I followed.
- I have created Category options
2 ) I have created Category
Dose (Premiere dose , Deuxieme dose)
Genre (Masculin, Feminin)
Until this step the analytics work well
But when I create category combination as below, analytics not run anymore.
Here are generated category option combination
here are the logs obtained with sudo dhis2-logview -f hmis.
I see! Thanks for sharing, and are there any errors in the Browser’s developer tools both the Console and the Network tabs? Please open the tools before running the analytics then perform the action and take a screenshot. 
Hello @Gassim , we can close this topic. it’s working now, but I can’t explain how and why. 
Regards.
1 Like
Lucky! (:
You’re welcome, and thank you for the update!