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


(Ioannis Oikonomou) #1

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


(Ioannis Oikonomou) #2

Anybody from SonarQube dev team maybe?


(Mirko Friedenhagen) #3

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


(Ioannis Oikonomou) #4

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


(Mirko Friedenhagen) #5

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 :slight_smile: