runsolver Copyright (C) 2010 Olivier ROUSSEL This is runsolver version 3.2.9a (svn: 651) This program is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. command line: runsolver -s SIGUSR1 -M 1124 -C 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.result -sum(solution,installedsize),-count(removed) Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 seconds Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 0.87 0.94 0.90 2/59 23042 /proc/meminfo: memFree=395240/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9136 CPUtime=0 /proc/23042/stat : 23042 (aspcud-basic) R 23041 23042 1733 0 -1 4202496 331 0 0 0 0 0 0 0 20 0 1 0 115810288 9355264 239 18446744073709551615 4194304 5129932 140734849978160 140734849976728 140486510793041 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2284 239 200 229 0 44 0 [startup+0.190538 s] /proc/loadavg: 0.87 0.94 0.90 2/59 23042 /proc/meminfo: memFree=395240/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=0.05 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 730 3614 0 0 1 0 2 2 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976816 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 Current children cumulated CPU time (s) 0.05 Current children cumulated vsize (KiB) 9212 [startup+0.200314 s] /proc/loadavg: 0.87 0.94 0.90 2/59 23042 /proc/meminfo: memFree=395240/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=0.05 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 730 3614 0 0 1 0 2 2 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976816 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 Current children cumulated CPU time (s) 0.05 Current children cumulated vsize (KiB) 9212 [startup+0.300277 s] /proc/loadavg: 0.87 0.94 0.90 2/59 23042 /proc/meminfo: memFree=395240/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=0.05 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 730 3614 0 0 1 0 2 2 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976816 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 Current children cumulated CPU time (s) 0.05 Current children cumulated vsize (KiB) 9212 [startup+0.700241 s] /proc/loadavg: 0.87 0.94 0.90 2/59 23042 /proc/meminfo: memFree=395240/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=0.05 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 730 3614 0 0 1 0 2 2 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976816 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 Current children cumulated CPU time (s) 0.05 Current children cumulated vsize (KiB) 9212 [startup+1.5003 s] /proc/loadavg: 0.87 0.94 0.90 2/61 23058 /proc/meminfo: memFree=359380/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=0.05 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 730 3614 0 0 1 0 2 2 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976816 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 [pid=23058] ppid=23042 vsize=51240 CPUtime=1.43 /proc/23058/stat : 23058 (cudf2lp) R 23042 23042 1733 0 -1 4202496 14349 0 0 0 137 6 0 0 20 0 1 0 115810291 52469760 10950 18446744073709551615 4194304 5690517 140734724113840 140734724111480 5006663 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0 /proc/23058/statm: 12810 10950 160 366 0 12441 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 60452 [startup+3.10032 s] /proc/loadavg: 0.87 0.94 0.90 2/61 23058 /proc/meminfo: memFree=326644/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=3 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 755 28563 0 0 1 0 282 17 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976816 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 Current children cumulated CPU time (s) 3 Current children cumulated vsize (KiB) 9212 [startup+6.30031 s] /proc/loadavg: 0.88 0.94 0.90 2/61 23059 /proc/meminfo: memFree=249392/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=3 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 755 28563 0 0 1 0 282 17 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976816 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 [pid=23059] ppid=23042 vsize=174260 CPUtime=3.23 /proc/23059/stat : 23059 (gringo) R 23042 23042 1733 0 -1 4202496 42516 0 0 0 308 15 0 0 20 0 1 0 115810591 178442240 37848 18446744073709551615 4194304 6531320 140735192189840 140735192186264 4596844 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0 /proc/23059/statm: 43565 37848 283 571 0 42986 0 Current children cumulated CPU time (s) 6.23 Current children cumulated vsize (KiB) 183472 [startup+12.7004 s] /proc/loadavg: 0.89 0.94 0.90 2/62 23061 /proc/meminfo: memFree=246284/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=8.64 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 793 113882 0 0 1 0 804 59 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976224 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 [pid=23060] ppid=23042 vsize=107736 CPUtime=3.89 /proc/23060/stat : 23060 (clasp) R 23042 23042 1733 0 -1 4202496 32253 0 0 0 378 11 0 0 20 0 1 0 115811161 110321664 26577 18446744073709551615 4194304 6238623 140735678346544 140735678343568 4687643 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/23060/statm: 26934 26577 263 500 0 26431 0 [pid=23061] ppid=23042 vsize=22040 CPUtime=0.02 /proc/23061/stat : 23061 (parse.py) S 23042 23042 1733 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115811161 22568960 1128 18446744073709551615 4194304 6642060 140736376317632 140736376315992 140162675640096 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/23061/statm: 5510 1128 508 598 0 596 0 Current children cumulated CPU time (s) 12.55 Current children cumulated vsize (KiB) 138988 [startup+25.5004 s] /proc/loadavg: 0.92 0.94 0.90 2/62 23061 /proc/meminfo: memFree=246160/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=8.64 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 793 113882 0 0 1 0 804 59 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976224 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 [pid=23060] ppid=23042 vsize=107736 CPUtime=16.57 /proc/23060/stat : 23060 (clasp) R 23042 23042 1733 0 -1 4202496 32285 0 0 0 1646 11 0 0 20 0 1 0 115811161 110321664 26609 18446744073709551615 4194304 6238623 140735678346544 140735678343568 4355569 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/23060/statm: 26934 26609 263 500 0 26431 0 [pid=23061] ppid=23042 vsize=22040 CPUtime=0.02 /proc/23061/stat : 23061 (parse.py) S 23042 23042 1733 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115811161 22568960 1128 18446744073709551615 4194304 6642060 140736376317632 140736376315992 140162675640096 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/23061/statm: 5510 1128 508 598 0 596 0 Current children cumulated CPU time (s) 25.23 Current children cumulated vsize (KiB) 138988 [startup+51.1004 s] /proc/loadavg: 0.94 0.95 0.91 2/62 23061 /proc/meminfo: memFree=246160/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=8.64 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 793 113882 0 0 1 0 804 59 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976224 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 [pid=23060] ppid=23042 vsize=107736 CPUtime=41.91 /proc/23060/stat : 23060 (clasp) R 23042 23042 1733 0 -1 4202496 32285 0 0 0 4180 11 0 0 20 0 1 0 115811161 110321664 26609 18446744073709551615 4194304 6238623 140735678346544 140735678343568 4332534 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/23060/statm: 26934 26609 263 500 0 26431 0 [pid=23061] ppid=23042 vsize=22040 CPUtime=0.02 /proc/23061/stat : 23061 (parse.py) S 23042 23042 1733 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115811161 22568960 1128 18446744073709551615 4194304 6642060 140736376317632 140736376315992 140162675640096 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/23061/statm: 5510 1128 508 598 0 596 0 Current children cumulated CPU time (s) 50.57 Current children cumulated vsize (KiB) 138988 [startup+102.3 s] /proc/loadavg: 0.97 0.95 0.91 2/62 23061 /proc/meminfo: memFree=160104/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=8.64 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 793 113882 0 0 1 0 804 59 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976224 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 [pid=23060] ppid=23042 vsize=198676 CPUtime=92.73 /proc/23060/stat : 23060 (clasp) R 23042 23042 1733 0 -1 4202496 53733 0 0 0 9248 25 0 0 20 0 1 0 115811161 203444224 48057 18446744073709551615 4194304 6238623 140735678346544 140735678343568 4409910 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/23060/statm: 49669 48057 263 500 0 49166 0 [pid=23061] ppid=23042 vsize=22040 CPUtime=0.02 /proc/23061/stat : 23061 (parse.py) S 23042 23042 1733 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115811161 22568960 1128 18446744073709551615 4194304 6642060 140736376317632 140736376315992 140162675640096 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/23061/statm: 5510 1128 508 598 0 596 0 Current children cumulated CPU time (s) 101.39 Current children cumulated vsize (KiB) 229928 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+156.9 s] /proc/loadavg: 1.30 1.03 0.94 2/62 23312 /proc/meminfo: memFree=34208/1022884 swapFree=0/0 [pid=23042] ppid=23041 vsize=9212 CPUtime=8.64 /proc/23042/stat : 23042 (aspcud-basic) S 23041 23042 1733 0 -1 4202496 793 113882 0 0 1 0 804 59 20 0 1 0 115810288 9433088 364 18446744073709551615 4194304 5129932 140734849978160 140734849976224 140486510928990 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/23042/statm: 2303 364 303 229 0 63 0 [pid=23060] ppid=23042 vsize=207692 CPUtime=141.39 /proc/23060/stat : 23060 (clasp) R 23042 23042 1733 0 -1 4202496 56405 0 0 0 14108 31 0 0 20 0 1 0 115811161 212676608 50729 18446744073709551615 4194304 6238623 140735678346544 140735678343568 4409871 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/23060/statm: 51923 50729 263 500 0 51420 0 [pid=23061] ppid=23042 vsize=22040 CPUtime=0.02 /proc/23061/stat : 23061 (parse.py) S 23042 23042 1733 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 115811161 22568960 1128 18446744073709551615 4194304 6642060 140736376317632 140736376315992 140162675640096 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/23061/statm: 5510 1128 508 598 0 596 0 Current children cumulated CPU time (s) 150.05 Current children cumulated vsize (KiB) 238944 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 156.949 CPU time (s): 150.105 CPU user time (s): 149.173 CPU system time (s): 0.932058 CPU usage (%): 95.6399 Max. virtual memory (cumulated for all children) (KiB): 371088 getrusage(RUSAGE_CHILDREN,...) data: user time used= 149.173 system time used= 0.932058 maximum resident set size= 306200 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 172699 page faults= 1 swaps= 0 block input operations= 43080 block output operations= 37656 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 73 involuntary context switches= 19542 runsolver used 0.336021 second user time and 0.636039 second system time The end