Upgrade process extremely slow because of very big PROJECT_MEASURES table (85 million rows)

gecon27 · April 9, 2019, 6:32pm

Hello all,

We are trying to upgrade our SonarQube instance from version 5.6.6 to version 6.7.6.
Our database is Oracle 11g and the size of the database is as below. Note the size of the PROJECT_MEASURES table which is approx. 85 million rows. Database is in NOARCHIVELOG mode and indexes have been rebuilt.
Problem is that the upgrade process is running for almost 7 days and projection is that it will take 25+ days to finish. The reason is that the rate that the data from table PROJECT_MEASURES is processed is extremely slow, i.e. 0 or 4 items/sec.
Any advice please?

Table	Size		Rows
SONAR.“PROJECT_MEASURES”	3.787	GB	84181004	rows
SONAR.“FILE_SOURCES”	793.5	MB	92737	rows
SONAR.“ISSUES”	137.1	MB	488958	rows
SONAR.“SNAPSHOTS”	126.5	MB	1237124	rows
SONAR.“RESOURCE_INDEX”	87.38	MB	1938916	rows
SONAR.“PROJECTS”	73	MB	138641	rows
SONAR.“ISSUE_CHANGES”	6.715	MB	47827	rows
SONAR.“RULES”	22.28	MB	4679	rows
SONAR.“ACTIVITIES”	2.006	MB	5524	rows
SONAR.“EVENTS”	1.574	MB	21065	rows
SONAR.“DUPLICATIONS_INDEX”	1.42	MB	30161	rows
SONAR.“CE_ACTIVITY”	492.7	KB	3032	rows
SONAR.“NOTIFICATIONS”	5.445	KB	0	rows
SONAR.“PROJECT_LINKS”	480.5	KB	3831	rows
SONAR.“ACTIVE_RULES”	265.9	KB	6511	rows
SONAR.“PROPERTIES”	23.79	KB	158	rows
SONAR.“RULES_PARAMETERS”	128.6	KB	992	rows
SONAR.“ISSUE_FILTERS”	8.32	KB	3	rows
SONAR.“MEASURE_FILTERS”	9.125	KB	4	rows
SONAR.“METRICS”	50.74	KB	340	rows
SONAR.“WIDGETS”	21.17	KB	154	rows
SONAR.“ACTIVE_DASHBOARDS”	7.664	KB	62	rows
SONAR.“ACTIVE_RULE_PARAMETERS”	34.56	KB	577	rows
SONAR.“CE_QUEUE”	8.39	KB	0	rows
SONAR.“DASHBOARDS”	9.679	KB	20	rows
SONAR.“GROUPS”	6.851	KB	2	rows
SONAR.“GROUPS_USERS”	5.523	KB	2	rows
SONAR.“GROUP_ROLES”	21.9	KB	642	rows
SONAR.“LOADED_TEMPLATES”	8.054	KB	56	rows
SONAR.“MANUAL_MEASURES”	8.453	KB	0	rows
SONAR.“MEASURE_FILTER_FAVOURITES”	6.445	KB	2	rows
SONAR.“PERMISSION_TEMPLATES”	8	KB	3	rows
SONAR.“PERM_TEMPLATES_GROUPS”	7.812	KB	13	rows
SONAR.“PERM_TEMPLATES_USERS”	7.789	KB	12	rows
SONAR.“PROJECT_QPROFILES”	7.109	KB	22	rows
SONAR.“QUALITY_GATES”	6.421	KB	3	rows
SONAR.“QUALITY_GATE_CONDITIONS”	9.546	KB	25	rows
SONAR.“RULES_PROFILES”	12.41	KB	41	rows
SONAR.“SCHEMA_MIGRATIONS”	8.125	KB	393	rows
SONAR.“USERS”	17.55	KB	40	rows
SONAR.“USER_ROLES”	17.33	KB	419	rows
SONAR.“USER_TOKENS”	6.976	KB	2	rows
SONAR.“WIDGET_PROPERTIES”	12.99	KB	192	rows
SONAR.“AUTHORS”	0	KB	0	rows
SONAR.“ISSUE_FILTER_FAVOURITES”	0	KB	0	rows

Log file:

2019.04.02 18:22:35 INFO  web[][o.s.p.ProcessEntryPoint] Starting web
2019.04.02 18:22:36 INFO  web[][o.a.t.u.n.NioSelectorPool] Using a shared selector for servlet write/read
2019.04.02 18:22:36 INFO  web[][o.e.p.PluginsService] no modules loaded
2019.04.02 18:22:36 INFO  web[][o.e.p.PluginsService] loaded plugin [org.elasticsearch.index.reindex.ReindexPlugin]
2019.04.02 18:22:36 INFO  web[][o.e.p.PluginsService] loaded plugin [org.elasticsearch.join.ParentJoinPlugin]
2019.04.02 18:22:36 INFO  web[][o.e.p.PluginsService] loaded plugin [org.elasticsearch.percolator.PercolatorPlugin]
2019.04.02 18:22:36 INFO  web[][o.e.p.PluginsService] loaded plugin [org.elasticsearch.transport.Netty4Plugin]
2019.04.02 18:22:37 INFO  web[][o.s.s.e.EsClientProvider] Connected to local Elasticsearch: [127.0.0.1:9001]
2019.04.02 18:22:37 INFO  web[][o.s.s.p.LogServerVersion] SonarQube Server / 6.7.6.38781 / 302f75de1ec5df6e983970f3c76b86ee02b1cd26
2019.04.02 18:22:37 INFO  web[][o.sonar.db.Database] Create JDBC data source for jdbc:oracle:thin:@XXX.XX.XX.XX:1521:SONARDB
2019.04.02 18:22:39 INFO  web[][o.s.s.p.ServerFileSystemImpl] SonarQube home: /opt/sonarqube-6.7.6
2019.04.02 18:22:39 INFO  web[][o.s.s.u.SystemPasscodeImpl] System authentication by passcode is disabled
2019.04.02 18:22:45 WARN  web[][o.s.s.p.DatabaseServerCompatibility] Database must be upgraded. Please backup database and browse /setup
2019.04.02 18:22:46 INFO  web[][o.s.s.p.Platform] Database needs migration
2019.04.02 18:22:46 INFO  web[][o.s.s.p.w.MasterServletFilter] Initializing servlet filter org.sonar.server.ws.WebServiceFilter@cb9ee20 [pattern=UrlPattern{inclusio
ns=[/api/system/migrate_db/*, ...], exclusions=[/api/properties*, ...]}]
2019.04.02 18:22:46 INFO  web[][o.s.s.a.EmbeddedTomcat] HTTP connector enabled on port 9000
2019.04.02 18:23:09 INFO  web[][o.s.s.p.d.m.DatabaseMigrationImpl] Starting DB Migration and container restart
2019.04.02 18:23:09 INFO  web[][DbMigrations] Executing DB migrations...
2019.04.02 18:23:09 INFO  web[][DbMigrations] #1200 'Create table PERM_TPL_CHARACTERISTICS'...
2019.04.02 18:23:11 INFO  web[][DbMigrations] #1200 'Create table PERM_TPL_CHARACTERISTICS': success | time=1770ms
2019.04.02 18:23:11 INFO  web[][DbMigrations] #1205 'Drop index resource_index_rid from RESOURCE_INDEX'...
2019.04.02 18:23:11 INFO  web[][DbMigrations] #1205 'Drop index resource_index_rid from RESOURCE_INDEX': success | time=358ms
2019.04.02 18:23:11 INFO  web[][DbMigrations] #1207 'Drop unused columns on PROJECT_MEASURES'...
2019.04.02 18:23:12 INFO  web[][DbMigrations] #1207 'Drop unused columns on PROJECT_MEASURES': success | time=878ms
2019.04.02 18:23:12 INFO  web[][DbMigrations] #1208 'Add columns SNAPSHOTS.*COMPONENT_UUID'...
2019.04.02 18:23:12 INFO  web[][DbMigrations] #1208 'Add columns SNAPSHOTS.*COMPONENT_UUID': success | time=230ms
2019.04.02 18:23:12 INFO  web[][DbMigrations] #1209 'Populate column SNAPSHOTS.*COMPONENT_UUID'...
2019.04.02 18:24:14 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 139262 snapshots processed (2321 items/sec)
2019.04.02 18:25:14 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 374291 snapshots processed (3917 items/sec)
2019.04.02 18:26:14 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 647541 snapshots processed (4554 items/sec)
2019.04.02 18:27:14 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 890541 snapshots processed (4050 items/sec)
2019.04.02 18:28:14 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 1046041 snapshots processed (2591 items/sec)
2019.04.02 18:28:58 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 1237124 snapshots processed (3184 items/sec)
2019.04.02 18:28:58 INFO  web[][DbMigrations] #1209 'Populate column SNAPSHOTS.*COMPONENT_UUID': success | time=345365ms
2019.04.02 18:28:58 INFO  web[][DbMigrations] #1210 'Create temporary indices for migration 1211'...
2019.04.02 18:28:59 INFO  web[][DbMigrations] #1210 'Create temporary indices for migration 1211': success | time=968ms
2019.04.02 18:28:59 INFO  web[][DbMigrations] #1211 'Clean orphan rows in SNAPSHOTS'...
2019.04.02 18:29:59 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 499 snapshots processed (8 items/sec)
2019.04.02 18:30:59 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 1249 snapshots processed (12 items/sec)
2019.04.02 18:31:59 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 1999 snapshots processed (12 items/sec)
2019.04.02 18:32:59 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 2749 snapshots processed (12 items/sec)
2019.04.02 18:33:16 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 3007 snapshots processed (4 items/sec)
2019.04.02 18:33:16 INFO  web[][DbMigrations] #1211 'Clean orphan rows in SNAPSHOTS': success | time=257012ms
2019.04.02 18:33:16 INFO  web[][DbMigrations] #1212 'Drop temporary indices for migration 1211'...
2019.04.02 18:33:16 INFO  web[][DbMigrations] #1212 'Drop temporary indices for migration 1211': success | time=290ms
2019.04.02 18:33:16 INFO  web[][DbMigrations] #1213 'Make column SNAPSHOTS.UUID not nullable'...
2019.04.02 18:34:06 INFO  web[][DbMigrations] #1213 'Make column SNAPSHOTS.UUID not nullable': success | time=50191ms
2019.04.02 18:34:06 INFO  web[][DbMigrations] #1214 'Drop columns SNAPSHOTS.SNAPSHOT_*_ID'...
2019.04.02 18:34:07 INFO  web[][DbMigrations] #1214 'Drop columns SNAPSHOTS.SNAPSHOT_*_ID': success | time=1242ms
2019.04.02 18:34:07 INFO  web[][DbMigrations] #1215 'Drop columns SNAPSHOTS.*_ID'...
2019.04.02 18:34:10 INFO  web[][DbMigrations] #1215 'Drop columns SNAPSHOTS.*_ID': success | time=2229ms
2019.04.02 18:34:10 INFO  web[][DbMigrations] #1216 'Add column PROJECT_MEASURES.COMPONENT_UUID'...
2019.04.02 18:34:10 INFO  web[][DbMigrations] #1216 'Add column PROJECT_MEASURES.COMPONENT_UUID': success | time=66ms
2019.04.02 18:34:10 INFO  web[][DbMigrations] #1217 'Populate column PROJECT_MEASURES.COMPONENT_UUID'...
2019.04.02 18:35:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 0 measures processed (0 items/sec)
2019.04.02 18:36:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 0 measures processed (0 items/sec)
2019.04.02 18:37:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 0 measures processed (0 items/sec)
2019.04.02 18:38:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 0 measures processed (0 items/sec)
2019.04.02 18:39:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 0 measures processed (0 items/sec)
2019.04.02 18:40:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 249 measures processed (4 items/sec)
2019.04.02 18:41:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 499 measures processed (4 items/sec)
2019.04.02 18:42:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 999 measures processed (8 items/sec)
2019.04.02 18:43:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 1499 measures processed (8 items/sec)
2019.04.02 18:44:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 1749 measures processed (4 items/sec)
2019.04.02 18:45:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 2249 measures processed (8 items/sec)
2019.04.02 18:46:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 2749 measures processed (8 items/sec)
2019.04.02 18:47:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 2999 measures processed (4 items/sec)
2019.04.02 18:48:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 3249 measures processed (4 items/sec)
2019.04.02 18:49:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 3499 measures processed (4 items/sec)
2019.04.02 18:50:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 3749 measures processed (4 items/sec)
2019.04.02 18:51:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 3999 measures processed (4 items/sec)
2019.04.02 18:52:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 4249 measures processed (4 items/sec)
2019.04.02 18:53:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 4499 measures processed (4 items/sec)
2019.04.02 18:54:10 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 4749 measures processed (4 items/sec)
{ … after 7 fays … }
2019.04.09 21:17:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 232999 measures processed (4 items/sec)
2019.04.09 21:18:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 232999 measures processed (0 items/sec)
2019.04.09 21:19:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 232999 measures processed (0 items/sec)
2019.04.09 21:20:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 232999 measures processed (0 items/sec)
2019.04.09 21:21:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 232999 measures processed (0 items/sec)
2019.04.09 21:22:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 232999 measures processed (0 items/sec)
2019.04.09 21:23:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 233249 measures processed (4 items/sec)
2019.04.09 21:24:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 233249 measures processed (0 items/sec)
2019.04.09 21:25:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 233249 measures processed (0 items/sec)
2019.04.09 21:26:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 233249 measures processed (0 items/sec)
2019.04.09 21:27:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 233499 measures processed (4 items/sec)
2019.04.09 21:28:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 233499 measures processed (0 items/sec)
2019.04.09 21:29:36 INFO  web[][o.s.s.p.d.m.s.MassUpdate] 233499 measures processed (0 items/sec)

Thank you,
Giannis

gecon27 · April 10, 2019, 8:45am

Anybody from SonarQube dev team maybe?

mfriedenhagen · April 10, 2019, 7:51pm

Hello,

just for the record:

Today I migrated SQ 5.6.6 to SQ 6.7.6 (PostgresSQL 10)
Sizes after migration:

      relation      | total_size 
--------------------+------------
 project_measures   | 19 GB
 projects           | 834 MB
 duplications_index | 782 MB
 file_sources       | 640 MB
 snapshots          | 253 MB
 issues             | 99 MB
 ce_activity        | 69 MB
 issue_changes      | 62 MB
 events             | 45 MB
 rules              | 12 MB

project_measures contains ~ 32M rows

I did this once on my Macbook Pro (small one with i5) (both PostgreSQL 10 and SQ running in Docker containers), this took about 50 minutes.
Doing the same between took 2 KVMs took 4h54m.

Regards
Mirko

gecon27 · April 16, 2019, 7:20am

Thank you Mirko.
Indeed, I took an export of the database in an Oracle XE instance on my laptop and the upgrade took just a few hours. Then I moved it back to the server and everything seems to be working fine.
Thank you for pointing me to the right direction!

Regards,
Giannis

mfriedenhagen · April 16, 2019, 1:18pm

You are welcome. I just today migrated on my Notebook (with SSDs) and the migration took about 50 minutes again. Afterwards I just nuked the database on the KVM and did PGPASSWORD=sonar pg_dump -h localhost -U sonar -d sonar | PGPASSWORD=LIVE_PASSWORD psql -h LIVEHOST -U sonar -d sonar which took about 50 minutes instead of 5 hours