Found the following entries in /var/log/message-20160403
<.. did see many times> Apr 5 07:01:03 localhost sudo[6832]: pam_unix(sudo:session): session opened for user apache by (uid=0) Apr 5 07:01:03 localhost sudo[6832]: pam_unix(sudo:session): session closed for user apache Apr 5 07:01:04 localhost sudo[6846]: root : TTY=unknown ; PWD=/var/www/de.oddb.org/svc/oddbd ; USER=apache ; COMMAND=/usr/bin/envdir ./env /usr/bin/ruby -rubygems /var/ww/var/www/de.oddb.org/bin/oddbd <.. till here> Apr 5 07:49:10 localhost kernel: ruby invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0 Apr 5 07:49:10 localhost kernel: ruby cpuset=/ mems_allowed=0 Apr 5 07:49:10 localhost kernel: CPU: 3 PID: 23082 Comm: ruby Not tainted 4.0.5 #3 Apr 5 07:49:10 localhost kernel: Hardware name: Supermicro X7DWU/X7DWU, BIOS 1.2 11/04/2008 Apr 5 07:49:10 localhost kernel: ffff88007faab9c8 ffff88007faab9d8 ffffffff816bc34e 0000000000000000 Apr 5 07:49:10 localhost kernel: ffff8803623ac000 ffff88007faaba58 ffffffff816bb8b4 ffffffff81c7d840 Apr 5 07:49:10 localhost kernel: 0000000000000206 0000000000000046 0000000000000206 0000000000000000 Apr 5 07:49:10 localhost kernel: Call Trace: Apr 5 07:49:10 localhost kernel: [<ffffffff816bc34e>] dump_stack+0x45/0x57 Apr 5 07:49:10 localhost kernel: [<ffffffff816bb8b4>] dump_header.isra.9+0x75/0x1e2 Apr 5 07:49:10 localhost kernel: [<ffffffff816c3820>] ? _raw_spin_unlock_irqrestore+0x48/0x4d Apr 5 07:49:10 localhost kernel: [<ffffffff810e927a>] oom_kill_process+0x91/0x32e Apr 5 07:49:10 localhost kernel: [<ffffffff81073c70>] ? lock_release+0x196/0x230 Apr 5 07:49:10 localhost kernel: [<ffffffff810e9965>] __out_of_memory+0x401/0x41c Apr 5 07:49:10 localhost kernel: [<ffffffff810e9abf>] out_of_memory+0x4f/0x66 Apr 5 07:49:10 localhost kernel: [<ffffffff810ed9d1>] __alloc_pages_nodemask+0x684/0x729 Apr 5 07:49:10 localhost kernel: [<ffffffff8111e362>] alloc_pages_current+0xa7/0xc4 Apr 5 07:49:10 localhost kernel: [<ffffffff810e6476>] __page_cache_alloc+0xfc/0x10b Apr 5 07:49:10 localhost kernel: [<ffffffff810e8323>] filemap_fault+0x224/0x377 Apr 5 07:49:10 localhost kernel: [<ffffffff81073c70>] ? lock_release+0x196/0x230 Apr 5 07:49:10 localhost kernel: [<ffffffff811061f7>] __do_fault+0x38/0x66 Apr 5 07:49:10 localhost kernel: [<ffffffff81073c70>] ? lock_release+0x196/0x230 Apr 5 07:49:10 localhost kernel: [<ffffffff816c379f>] ? _raw_spin_unlock+0x23/0x27 Apr 5 07:49:10 localhost kernel: [<ffffffff81109059>] handle_mm_fault+0x2c4/0xb43 Apr 5 07:49:10 localhost kernel: [<ffffffff810734cc>] ? lock_acquire+0xba/0x105 Apr 5 07:49:10 localhost kernel: [<ffffffff81032fc7>] __do_page_fault+0x224/0x398 Apr 5 07:49:10 localhost kernel: [<ffffffff81281b5d>] ? trace_hardirqs_off_thunk+0x3a/0x3c Apr 5 07:49:10 localhost kernel: [<ffffffff81033160>] do_page_fault+0x25/0x27 Apr 5 07:49:10 localhost kernel: [<ffffffff816c5cd8>] page_fault+0x28/0x30 <..> Apr 5 07:49:16 localhost kernel: [23171] 81 23171 73723 13618 85 4 0 0 ruby Apr 5 07:49:16 localhost kernel: Out of memory: Kill process 19558 (ruby) score 1014 or sacrifice child Apr 5 07:49:16 localhost kernel: Killed process 19558 (ruby) total-vm:1344372kB, anon-rss:407584kB, file-rss:0kB Apr 5 07:51:46 localhost sudo[23180]: root : TTY=unknown ; PWD=/var/www/oddb.org ; USER=apache ; COMMAND=/usr/local/bin/ruby bin/oddbd google_crawler <.. Now the import_daily gets killed> Apr 5 07:49:22 localhost kernel: Out of memory: Kill process 6811 (ruby) score 826 or sacrifice child Apr 5 07:49:22 localhost kernel: Killed process 6811 (ruby) total-vm:28669060kB, anon-rss:23758248kB, file-rss:0kB
The started job was (from log/job.pid) 6811,import_daily,2016-04-05 07:01:36 +0200
.
Why the hell does the import_swissmedic consume so much memory?
The last lines in log/oddb/debug/2015/04.log are:
2016-04-05 07:48:59 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:821:in `block (2 levels) in update_compositions': /var/www/oddb.org/src/plugin/swissmedic.rb: 821 00670/01 using oid 9479041 source collagenum ex equum, fibrinogenum humanum 5.5 mg, t 2016-04-05 07:49:00 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:680:in `update_active_agent': update_active_agent 00670/01 Riboflavinum true dose 18.2 µg 2016-04-05 07:49:00 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:821:in `block (2 levels) in update_compositions': /var/www/oddb.org/src/plugin/swissmedic.rb: 821 00670/01 using oid 9479041 source collagenum ex equum, fibrinogenum humanum 5.5 mg, t 2016-04-05 07:49:00 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:680:in `update_active_agent': update_active_agent 00670/01 Albuminum Humanum false dose 0 2016-04-05 07:49:01 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:821:in `block (2 levels) in update_compositions': /var/www/oddb.org/src/plugin/swissmedic.rb: 821 00670/01 using oid 9479041 source collagenum ex equum, fibrinogenum humanum 5.5 mg, t 2016-04-05 07:49:01 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:680:in `update_active_agent': update_active_agent 00670/01 Natrii Chloridum false dose 0 2016-04-05 07:49:01 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:821:in `block (2 levels) in update_compositions': /var/www/oddb.org/src/plugin/swissmedic.rb: 821 00670/01 using oid 9479041 source collagenum ex equum, fibrinogenum humanum 5.5 mg, t 2016-04-05 07:49:02 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:680:in `update_active_agent': update_active_agent 00670/01 Natrii Citras Dihydricus false dose 0 2016-04-05 07:49:02 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:821:in `block (2 levels) in update_compositions': /var/www/oddb.org/src/plugin/swissmedic.rb: 821 00670/01 using oid 9479041 source collagenum ex equum, fibrinogenum humanum 5.5 mg, t 2016-04-05 07:49:03 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:680:in `update_active_agent': update_active_agent 00670/01 L-arginini Hydrochloridum false dose 0
Adding a new thread to trace memory useage all minutes in import_swissmedic. Reloading the database and rerunning import_swissmedic on oddb-ci2.
Memory useage stays for a long time at around 2 GB (which is what I expected). After starting update_registrations it goes up to around 3124 MB. A couple of minutes it goes up to 3511 MB and never used more. Finished successfully on oddb-ci2.
Adding a GC.start at the beginning of update_registration and update_compositions. Reloading database and rerunning import to see whether the memory requirements go down. Used the same memory, taking 92 minutes, too. Pushing changes to thinpower and rerunning import there.
Pushed commits
When running at thinpower import_swissmedic eats much more memory, eg.
2016-04-05 13:59:27 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 12000 MB of memory 2016-04-05 14:00:50 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 22727 MB of memory
Whereas on oddb-ci2 I never did see something more than
2016-04-05 13:58:34 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:705:in `update_active_agent': update_active_agent 00670/01 L-arginini Hydrochloridum false dose 0 2016-04-05 13:59:27 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 12000 MB of memory 2016-04-05 14:00:50 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 22727 MB of memory 2016-04-05 14:02:12 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 31116 MB of memory 2016-04-05 14:06:44 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 32361 MB of memory 2016-04-05 14:12:16 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 32528 MB of memory 2016-04-05 14:21:29 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 32564 MB of memory 2016-04-05 14:34:10 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 32564 MB of memory 2016-04-05 14:49:41 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 32564 MB of memory 2016-04-05 15:03:37 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 32564 MB of memory 2016-04-05 15:18:36 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 32564 MB of memory
I would like to stop and restart all ruby/postgresql jobs on thinpower to see whether this makes a difference or not. Waiting for zeno to agree to this idea.
After restarting the import again, I could not find any other process using more memory and it got killed again.
2016-04-05 18:01:19 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:705:in `update_active_agent': update_active_agent 00670/01 L-arginini Hydrochloridum false dose 0 2016-04-05 18:01:54 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 9783 MB of memory 2016-04-05 18:03:19 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 19705 MB of memory 2016-04-05 18:04:42 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:161:in `trace_memory_useage': Using 29523 MB of memory
There must be a problem when (or after) updating the the update_active_agent 00670/01 L-arginini Hydrochloridum
When trying to compare this situation with the local imports I found 3 occurrences where this proceeded quite fast (< 3 seconds), eg.
2016-04-05 18:00:12 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:1113:in `update_registration': update_registration 00670 args {:ith_swissmedic=>"06.99.0.", :production_science=>"Blutprodukte", :vaccine=>true, :registration_date=>#<Date: 2004-09-27 ((2453276j,0s,0n),+0s,2299161j)>, :expiration_date=>#<Date: 2019-09-24 ((2458751j,0s,0n),+0s,2299161j)>, :renewal_flag=>false, :renewal_flag_swissmedic=>false, :inactive_date=>nil, :export_flag=>nil, :company=>:!company,374., :indication=>:!indication,711736.} 2016-04-05 18:01:04 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:837:in `block in update_compositions': update_compositions iksnr 00670 seqnr 01 comp_idx 0 parsed_comp #<ParseComposition:0x000000273a0148> <..> 2016-04-04 18:25:55 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:816:in `block (2 levels) in update_compositions': /var/www/oddb.org/src/plugin/swissmedic.rb: 816 00670/01 using oid 9479041 source collagenum ex equum, fibrinogenum humanum 5.5 mg, t 2016-04-04 18:25:56 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:675:in `update_active_agent': update_active_agent 00670/01 L-arginini Hydrochloridum false dose 0 2016-04-04 18:25:56 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:970:in `update_package': 00670/01/003 {} 2016-04-04 18:25:56 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:991:in `update_package': create 00670/01/003 ptr :!create,:!registration,00670!sequence,01!package,003.. package #<ODDB::Package:0x000000a2d14780> in :!registration,00670!sequence,01. ["001", "002", "011", "021", "003"] 2016-04-04 18:25:57 +0200: /var/www/oddb.org/src/plugin/swissmedic.rb:999:in `update_package': create part.oid 34716725 part.pointerBut on oddb-ci2 I have
psql --version psql (PostgreSQL) 8.4.17 enthält Unterstützung für Kommandozeilenbearbeitung
whereas on thinpower we still have
psql --version psql (PostgreSQL) 8.3.8 enthält Unterstützung für Kommandozeilenbearbeitung
Is this the problem?
Preparing an E-Mail to Zeno with estimations of effort to realize some changes for HIN.