OpenQuake Engine

Export phase in Event Based calculation takes longer than actual calculation

Bug #1169078 reported by Damiano Monelli
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenQuake Engine
Fix Released
High
Michele Simionato
OpenQuake Engine 1.0.0

Bug Description

When running an event based calculation on eth cluster, the 'export' phase took much longer than the actual calculation. As it can be seen from the reported log, the 'execution' phase started at 09:21:00 and ended at 09:23:44 (so about 3 minutes), while the 'export' phase started at 09:23:46 and ended at 09:39:16 (so about 16 minutes). So the export phase was roughly 5 times longer than the execution phase. We need to investigate if optimization of this phase is possible.

Input and configuration files are attached in order to reproduce the calculation. Note that in openquake.cfg block_size was set to 5.

damiano@gemcontrol:/usr/local/openquake/oq-engine$ bin/openquake --rh=~/PSHA_Models/California/job.ini --exports=xml
/usr/local/openquake/oq-engine/openquake/__init__.py:1: UserWarning: Module openquake was already imported from /usr/local/openquake/oq-engine/openquake/__init__.pyc, but /usr/lib/pymodules/python2.7 is being added to sys.path
  __import__('pkg_resources').declare_namespace(__name__)
[2013-04-15 09:20:05,267 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** pre_executing (hazard)
[2013-04-15 09:20:05,279 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** initializing sources
[2013-04-15 09:20:58,496 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** initializing site model
[2013-04-15 09:20:58,541 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** initializing realizations
[2013-04-15 09:21:00,475 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** executing (hazard)
[2013-04-15 09:21:05,109 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 2% complete
[2013-04-15 09:21:05,355 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 3% complete
[2013-04-15 09:21:05,734 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 4% complete
[2013-04-15 09:21:06,090 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 5% complete
[2013-04-15 09:21:06,361 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 6% complete
[2013-04-15 09:21:06,798 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 7% complete
[2013-04-15 09:21:07,158 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 8% complete
[2013-04-15 09:21:07,466 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 9% complete
[2013-04-15 09:21:07,628 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 10% complete
[2013-04-15 09:21:08,220 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 11% complete
[2013-04-15 09:21:08,336 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 12% complete
[2013-04-15 09:21:08,498 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 13% complete
[2013-04-15 09:21:08,736 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 14% complete
[2013-04-15 09:21:09,027 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 15% complete
[2013-04-15 09:21:09,403 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 16% complete
[2013-04-15 09:21:09,760 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 17% complete
[2013-04-15 09:21:10,188 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 18% complete
[2013-04-15 09:21:10,593 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 19% complete
[2013-04-15 09:21:10,943 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 20% complete
[2013-04-15 09:21:11,408 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 21% complete
[2013-04-15 09:21:12,000 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 22% complete
[2013-04-15 09:21:12,629 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 23% complete
[2013-04-15 09:21:13,346 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 24% complete
[2013-04-15 09:21:15,217 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 25% complete
[2013-04-15 09:21:19,469 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 26% complete
[2013-04-15 09:21:26,912 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 27% complete
[2013-04-15 09:21:40,477 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 28% complete
[2013-04-15 09:21:59,291 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 29% complete
[2013-04-15 09:22:12,537 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 30% complete
[2013-04-15 09:22:15,913 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 31% complete
[2013-04-15 09:22:18,535 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 32% complete
[2013-04-15 09:22:21,742 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 33% complete
[2013-04-15 09:22:24,343 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 34% complete
[2013-04-15 09:22:26,635 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 35% complete
[2013-04-15 09:22:28,046 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 36% complete
[2013-04-15 09:22:28,827 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 37% complete
[2013-04-15 09:22:29,412 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 38% complete
[2013-04-15 09:22:29,925 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 39% complete
[2013-04-15 09:22:30,383 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 40% complete
[2013-04-15 09:22:30,781 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 41% complete
[2013-04-15 09:22:31,144 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 42% complete
[2013-04-15 09:22:31,559 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 43% complete
[2013-04-15 09:22:31,854 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 44% complete
[2013-04-15 09:22:32,231 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 45% complete
[2013-04-15 09:22:32,554 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 46% complete
[2013-04-15 09:22:32,927 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 47% complete
[2013-04-15 09:22:33,272 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 48% complete
[2013-04-15 09:22:33,587 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 49% complete
[2013-04-15 09:22:33,915 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 50% complete
[2013-04-15 09:22:34,307 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 51% complete
[2013-04-15 09:22:34,583 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 52% complete
[2013-04-15 09:22:34,898 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 53% complete
[2013-04-15 09:22:35,315 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 54% complete
[2013-04-15 09:22:35,630 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 55% complete
[2013-04-15 09:22:35,869 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 56% complete
[2013-04-15 09:22:36,273 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 57% complete
[2013-04-15 09:22:36,570 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 58% complete
[2013-04-15 09:22:36,904 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 59% complete
[2013-04-15 09:22:37,302 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 60% complete
[2013-04-15 09:22:37,575 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 61% complete
[2013-04-15 09:22:37,888 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 62% complete
[2013-04-15 09:22:38,162 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 63% complete
[2013-04-15 09:22:38,387 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 64% complete
[2013-04-15 09:22:38,898 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 65% complete
[2013-04-15 09:22:39,319 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 66% complete
[2013-04-15 09:22:39,697 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 67% complete
[2013-04-15 09:22:40,104 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 68% complete
[2013-04-15 09:22:40,490 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 69% complete
[2013-04-15 09:22:40,918 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 70% complete
[2013-04-15 09:22:41,279 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 71% complete
[2013-04-15 09:22:41,732 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 72% complete
[2013-04-15 09:22:42,099 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 73% complete
[2013-04-15 09:22:42,566 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 74% complete
[2013-04-15 09:22:42,960 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 75% complete
[2013-04-15 09:22:43,355 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 76% complete
[2013-04-15 09:22:43,872 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 77% complete
[2013-04-15 09:22:44,586 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 78% complete
[2013-04-15 09:22:44,983 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 79% complete
[2013-04-15 09:22:45,409 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 80% complete
[2013-04-15 09:22:45,954 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 81% complete
[2013-04-15 09:22:46,459 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 82% complete
[2013-04-15 09:22:46,742 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 83% complete
[2013-04-15 09:22:47,098 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 84% complete
[2013-04-15 09:22:47,427 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 85% complete
[2013-04-15 09:22:47,809 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 86% complete
[2013-04-15 09:22:48,179 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 87% complete
[2013-04-15 09:22:48,519 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 88% complete
[2013-04-15 09:22:48,878 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 89% complete
[2013-04-15 09:22:49,324 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 90% complete
[2013-04-15 09:22:49,645 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 91% complete
[2013-04-15 09:22:49,912 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 92% complete
[2013-04-15 09:22:50,515 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 93% complete
[2013-04-15 09:22:57,496 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 94% complete
[2013-04-15 09:23:10,325 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 95% complete
[2013-04-15 09:23:17,057 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 96% complete
[2013-04-15 09:23:22,374 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 97% complete
[2013-04-15 09:23:23,255 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 98% complete
[2013-04-15 09:23:23,843 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** > hazard 99% complete
[2013-04-15 09:23:44,495 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** calculation 100% complete
[2013-04-15 09:23:44,502 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** post_executing (hazard)
[2013-04-15 09:23:44,509 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** post_processing (hazard)
[2013-04-15 09:23:46,579 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** export (hazard)
[2013-04-15 09:39:16,593 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** clean_up (hazard)
[2013-04-15 09:39:16,601 #199 gemcontrol.ethz.ch PROGRESS MainProcess/7612 root] ** complete (hazard)
Job 199 ran successfully
Calculation 188 results:
id | output_type | name
3678 | gmf | gmf-rlz-884
3679 | hazard_curve | hazard-curve-rlz-884-PGA
3680 | hazard_map | hazard-map(0.1)-PGA-rlz-884
3681 | hazard_map | hazard-map(0.02)-PGA-rlz-884
3677 | ses | ses-coll-rlz-884

Revision history for this message
Damiano Monelli (monelli) wrote :
Revision history for this message
Damiano Monelli (monelli) wrote :
Download full text (12.4 KiB)

As expected the situations gets worse when increasing the ses_per_logic_tree_path = 300 (in the above run it was set to 100). The calculation now takes 7 minutes and the export phase about 50 minutes.

damiano@gemcontrol:/usr/local/openquake/oq-engine$ bin/openquake --rh=~/PSHA_Models/California/job.ini --exports=xml
/usr/local/openquake/oq-engine/openquake/__init__.py:1: UserWarning: Module openquake was already imported from /usr/local/openquake/oq-engine/openquake/__init__.pyc, but /usr/lib/pymodules/python2.7 is being added to sys.path
  __import__('pkg_resources').declare_namespace(__name__)
[2013-04-15 10:23:55,063 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** pre_executing (hazard)
[2013-04-15 10:23:55,074 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** initializing sources
[2013-04-15 10:24:47,940 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** initializing site model
[2013-04-15 10:24:47,984 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** initializing realizations
[2013-04-15 10:24:50,386 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** executing (hazard)
[2013-04-15 10:24:58,443 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 1% complete
[2013-04-15 10:24:59,134 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 2% complete
[2013-04-15 10:25:00,340 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 3% complete
[2013-04-15 10:25:01,629 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 4% complete
[2013-04-15 10:25:02,808 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 5% complete
[2013-04-15 10:25:03,863 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 6% complete
[2013-04-15 10:25:04,775 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 7% complete
[2013-04-15 10:25:05,908 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 8% complete
[2013-04-15 10:25:06,795 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 9% complete
[2013-04-15 10:25:07,613 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 10% complete
[2013-04-15 10:25:09,077 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 11% complete
[2013-04-15 10:25:09,677 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 12% complete
[2013-04-15 10:25:10,439 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 13% complete
[2013-04-15 10:25:11,319 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 14% complete
[2013-04-15 10:25:12,554 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 15% complete
[2013-04-15 10:25:13,359 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 16% complete
[2013-04-15 10:25:14,062 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 17% complete
[2013-04-15 10:25:14,958 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 18% complete
[2013-04-15 10:25:15,682 #200 gemcontrol.ethz.ch PROGRESS MainProcess/8405 root] ** > hazard 19% complete
[2013...

Michele Simionato (michele-simionato)
Changed in oq-engine:
status: New → In Progress
assignee: nobody → Michele Simionato (michele-simionato)
Revision history for this message
Michele Simionato (michele-simionato) wrote :

https://github.com/gem/oq-engine/pull/1179

Michele Simionato (michele-simionato)
Changed in oq-engine:
status: In Progress → Confirmed
Revision history for this message
Michele Simionato (michele-simionato) wrote :

Finally solved here: https://github.com/gem/oq-engine/pull/1200

Michele Simionato (michele-simionato)
Changed in oq-engine:
status: Confirmed → Fix Committed
Daniele Viganò (daniele-vigano)
Changed in oq-engine:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.