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/e381ba7e-a192-11e0-8647-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/e381ba7e-a192-11e0-8647-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/e381ba7e-a192-11e0-8647-00163e1e087d.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 [startup+0 s] /proc/loadavg: 0.88 0.95 0.92 2/59 5762 /proc/meminfo: memFree=304656/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=3152 CPUtime=0 /proc/5762/stat : 5762 (runsolver) R 5761 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115852892 3227648 33 18446744073709551615 134512640 134586868 4288368288 4288366336 4152112176 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.14411 s] /proc/loadavg: 0.88 0.95 0.92 2/59 5762 /proc/meminfo: memFree=304656/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=0.02 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 730 3611 0 0 0 0 2 0 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529923136 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 9212 [startup+0.200259 s] /proc/loadavg: 0.88 0.95 0.92 2/59 5762 /proc/meminfo: memFree=304656/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=0.02 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 730 3611 0 0 0 0 2 0 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529923136 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 9212 [startup+0.300245 s] /proc/loadavg: 0.88 0.95 0.92 2/59 5762 /proc/meminfo: memFree=304656/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=0.02 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 730 3611 0 0 0 0 2 0 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529923136 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 9212 [startup+0.700166 s] /proc/loadavg: 0.88 0.95 0.92 2/59 5762 /proc/meminfo: memFree=304656/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=0.02 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 730 3611 0 0 0 0 2 0 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529923136 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 9212 [startup+1.50025 s] /proc/loadavg: 0.88 0.95 0.92 2/61 5778 /proc/meminfo: memFree=246104/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=0.02 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 730 3611 0 0 0 0 2 0 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529923136 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5778] ppid=5762 vsize=84612 CPUtime=1.42 /proc/5778/stat : 5778 (cudf2lp) R 5762 5762 1750 0 -1 4202496 23545 0 0 0 134 8 0 0 20 0 1 0 115852895 86642688 20146 18446744073709551615 4194304 5690517 140733592564528 140733592561656 4962121 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0 /proc/5778/statm: 21153 20146 168 366 0 20784 0 Current children cumulated CPU time (s) 1.44 Current children cumulated vsize (KiB) 93824 [startup+3.10026 s] /proc/loadavg: 0.89 0.95 0.92 2/61 5779 /proc/meminfo: memFree=260364/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=1.71 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 755 27616 0 0 0 0 159 12 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529923136 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5779] ppid=5762 vsize=152876 CPUtime=1.32 /proc/5779/stat : 5779 (gringo) R 5762 5762 1750 0 -1 4202496 36727 0 0 0 120 12 0 0 20 0 1 0 115853068 156545024 32059 18446744073709551615 4194304 6531320 140736145733280 140736145730456 5507373 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0 /proc/5779/statm: 38219 32059 284 571 0 37640 0 Current children cumulated CPU time (s) 3.03 Current children cumulated vsize (KiB) 162088 [startup+6.30031 s] /proc/loadavg: 0.89 0.95 0.92 2/62 5781 /proc/meminfo: memFree=233696/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=3.16 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 793 64347 0 0 0 0 289 27 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529922544 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5780] ppid=5762 vsize=42032 CPUtime=3.03 /proc/5780/stat : 5780 (clasp) R 5762 5762 1750 0 -1 4202496 12090 0 0 0 299 4 0 0 20 0 1 0 115853215 43040768 10168 18446744073709551615 4194304 6238623 140734531809856 140734531806880 4355623 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/5780/statm: 10508 10168 263 500 0 10005 0 [pid=5781] ppid=5762 vsize=22040 CPUtime=0 /proc/5781/stat : 5781 (parse.py) S 5762 5762 1750 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115853215 22568960 1127 18446744073709551615 4194304 6642060 140733903996032 140733903994392 140135316903712 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/5781/statm: 5510 1127 508 598 0 596 0 Current children cumulated CPU time (s) 6.19 Current children cumulated vsize (KiB) 73284 [startup+12.7003 s] /proc/loadavg: 0.90 0.95 0.92 2/62 5781 /proc/meminfo: memFree=233696/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=3.16 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 793 64347 0 0 0 0 289 27 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529922544 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5780] ppid=5762 vsize=42032 CPUtime=9.39 /proc/5780/stat : 5780 (clasp) R 5762 5762 1750 0 -1 4202496 12090 0 0 0 934 5 0 0 20 0 1 0 115853215 43040768 10168 18446744073709551615 4194304 6238623 140734531809856 140734531806880 4687681 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/5780/statm: 10508 10168 263 500 0 10005 0 [pid=5781] ppid=5762 vsize=22040 CPUtime=0 /proc/5781/stat : 5781 (parse.py) S 5762 5762 1750 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115853215 22568960 1127 18446744073709551615 4194304 6642060 140733903996032 140733903994392 140135316903712 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/5781/statm: 5510 1127 508 598 0 596 0 Current children cumulated CPU time (s) 12.55 Current children cumulated vsize (KiB) 73284 [startup+25.5003 s] /proc/loadavg: 0.92 0.96 0.92 2/62 5781 /proc/meminfo: memFree=232332/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=3.16 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 793 64347 0 0 0 0 289 27 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529922544 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5780] ppid=5762 vsize=43352 CPUtime=22.09 /proc/5780/stat : 5780 (clasp) R 5762 5762 1750 0 -1 4202496 12468 0 0 0 2204 5 0 0 20 0 1 0 115853215 44392448 10546 18446744073709551615 4194304 6238623 140734531809856 140734531806880 4406979 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/5780/statm: 10838 10546 263 500 0 10335 0 [pid=5781] ppid=5762 vsize=22040 CPUtime=0 /proc/5781/stat : 5781 (parse.py) S 5762 5762 1750 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115853215 22568960 1127 18446744073709551615 4194304 6642060 140733903996032 140733903994392 140135316903712 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/5781/statm: 5510 1127 508 598 0 596 0 Current children cumulated CPU time (s) 25.25 Current children cumulated vsize (KiB) 74604 [startup+51.1003 s] /proc/loadavg: 0.95 0.96 0.92 2/62 5781 /proc/meminfo: memFree=206416/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=3.16 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 793 64347 0 0 0 0 289 27 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529922544 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5780] ppid=5762 vsize=69388 CPUtime=47.51 /proc/5780/stat : 5780 (clasp) R 5762 5762 1750 0 -1 4202496 18914 0 0 0 4741 10 0 0 20 0 1 0 115853215 71053312 16992 18446744073709551615 4194304 6238623 140734531809856 140734531806880 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/5780/statm: 17347 16992 263 500 0 16844 0 [pid=5781] ppid=5762 vsize=22040 CPUtime=0 /proc/5781/stat : 5781 (parse.py) S 5762 5762 1750 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115853215 22568960 1127 18446744073709551615 4194304 6642060 140733903996032 140733903994392 140135316903712 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/5781/statm: 5510 1127 508 598 0 596 0 Current children cumulated CPU time (s) 50.67 Current children cumulated vsize (KiB) 100640 [startup+102.3 s] /proc/loadavg: 1.01 0.98 0.92 2/62 5781 /proc/meminfo: memFree=199720/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=3.16 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 793 64347 0 0 0 0 289 27 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529922544 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5780] ppid=5762 vsize=75856 CPUtime=98.34 /proc/5780/stat : 5780 (clasp) R 5762 5762 1750 0 -1 4202496 20573 0 0 0 9822 12 0 0 20 0 1 0 115853215 77676544 18651 18446744073709551615 4194304 6238623 140734531809856 140734531806880 4409871 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/5780/statm: 18964 18651 263 500 0 18461 0 [pid=5781] ppid=5762 vsize=22040 CPUtime=0 /proc/5781/stat : 5781 (parse.py) S 5762 5762 1750 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115853215 22568960 1127 18446744073709551615 4194304 6642060 140733903996032 140733903994392 140135316903712 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/5781/statm: 5510 1127 508 598 0 596 0 Current children cumulated CPU time (s) 101.5 Current children cumulated vsize (KiB) 107108 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+151.2 s] /proc/loadavg: 1.01 0.98 0.92 2/62 5781 /proc/meminfo: memFree=199596/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=3.16 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 793 64347 0 0 0 0 289 27 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529922544 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5780] ppid=5762 vsize=75856 CPUtime=146.89 /proc/5780/stat : 5780 (clasp) R 5762 5762 1750 0 -1 4202496 20573 0 0 0 14673 16 0 0 20 0 1 0 115853215 77676544 18651 18446744073709551615 4194304 6238623 140734531809856 140734531806880 4663111 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/5780/statm: 18964 18651 263 500 0 18461 0 [pid=5781] ppid=5762 vsize=22040 CPUtime=0 /proc/5781/stat : 5781 (parse.py) S 5762 5762 1750 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115853215 22568960 1127 18446744073709551615 4194304 6642060 140733903996032 140733903994392 140135316903712 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/5781/statm: 5510 1127 508 598 0 596 0 Current children cumulated CPU time (s) 150.05 Current children cumulated vsize (KiB) 107108 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+151.2 s] /proc/loadavg: 1.01 0.98 0.92 2/62 5781 /proc/meminfo: memFree=199596/1022884 swapFree=0/0 [pid=5762] ppid=5761 vsize=9212 CPUtime=3.16 /proc/5762/stat : 5762 (aspcud-basic) S 5761 5762 1750 0 -1 4202496 793 64347 0 0 0 0 289 27 20 0 1 0 115852892 9433088 365 18446744073709551615 4194304 5129932 140736529924480 140736529922544 139641397458014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0 /proc/5762/statm: 2303 365 303 229 0 63 0 [pid=5780] ppid=5762 vsize=75856 CPUtime=146.89 /proc/5780/stat : 5780 (clasp) R 5762 5762 1750 0 -1 4202496 20573 0 0 0 14673 16 0 0 20 0 1 0 115853215 77676544 18651 18446744073709551615 4194304 6238623 140734531809856 140734531806880 4663111 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0 /proc/5780/statm: 18964 18651 263 500 0 18461 0 [pid=5781] ppid=5762 vsize=22040 CPUtime=0 /proc/5781/stat : 5781 (parse.py) S 5762 5762 1750 0 -1 4202496 1318 0 0 0 0 0 0 0 20 0 1 0 115853215 22568960 1127 18446744073709551615 4194304 6642060 140733903996032 140733903994392 140135316903712 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0 /proc/5781/statm: 5510 1127 508 598 0 596 0 Current children cumulated CPU time (s) 150.05 Current children cumulated vsize (KiB) 107108 Child status: 0 Real time (s): 151.218 CPU time (s): 150.109 CPU user time (s): 149.649 CPU system time (s): 0.460028 CPU usage (%): 99.2667 Max. virtual memory (cumulated for all children) (KiB): 162088 getrusage(RUSAGE_CHILDREN,...) data: user time used= 149.649 system time used= 0.460028 maximum resident set size= 132544 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 87332 page faults= 0 swaps= 0 block input operations= 37048 block output operations= 18624 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 67 involuntary context switches= 17160 runsolver used 0.272017 second user time and 0.524032 second system time The end