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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand165.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand165.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand165.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.result Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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: 1.00 1.02 1.00 2/40 8504 /proc/meminfo: memFree=764048/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=3020 CPUtime=0 /proc/8504/stat : 8504 (runsolver) D 8503 8504 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 24 0 1 0 878672162 3092480 93 1283457024 134512640 134586868 4293316448 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/8504/statm: 755 93 62 19 0 53 0 [startup+0.113543 s] /proc/loadavg: 1.00 1.02 1.00 2/40 8504 /proc/meminfo: memFree=764048/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=0 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 538 2017 2 2 0 0 0 0 25 0 1 0 878672162 2654208 298 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 298 252 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.205565 s] /proc/loadavg: 1.00 1.02 1.00 2/40 8504 /proc/meminfo: memFree=764048/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=0 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 613 2216 3 3 0 0 0 0 25 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.305546 s] /proc/loadavg: 1.00 1.02 1.00 2/40 8504 /proc/meminfo: memFree=764048/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=0 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 613 2216 3 3 0 0 0 0 25 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.71051 s] /proc/loadavg: 1.00 1.02 1.00 2/40 8504 /proc/meminfo: memFree=764048/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=0 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 613 2216 3 3 0 0 0 0 25 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.5107 s] /proc/loadavg: 1.00 1.02 1.00 2/44 8518 /proc/meminfo: memFree=738820/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=0 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 613 2216 3 3 0 0 0 0 25 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=1868 CPUtime=0 /proc/8516/stat : 8516 (clasp) S 8504 8504 4159 34819 4229 4202496 267 0 16 0 0 0 0 0 22 0 1 0 878672174 1912832 152 1283457024 134512640 136223643 4287118528 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8516/statm: 467 152 138 418 0 47 0 [pid=8517] ppid=8504 vsize=2608 CPUtime=0 /proc/8517/stat : 8517 (gringo) S 8504 8504 4159 34819 4229 4202496 385 0 22 0 0 0 0 0 22 0 1 0 878672174 2670592 277 1283457024 134512640 136959103 4289463344 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8517/statm: 652 277 247 598 0 51 0 [pid=8518] ppid=8504 vsize=45440 CPUtime=1.04 /proc/8518/stat : 8518 (cudf2lp) R 8504 8504 4159 34819 4229 4202496 12457 0 14 0 100 4 0 0 25 0 1 0 878672174 46530560 10319 1283457024 134512640 135749571 4287122608 18446744073709551615 134572516 0 0 6 0 0 0 0 17 0 0 0 0 /proc/8518/statm: 11360 10319 127 302 0 11056 0 Current children cumulated CPU time (s) 1.04 Current children cumulated vsize (KiB) 52508 [startup+3.11505 s] /proc/loadavg: 1.00 1.02 1.00 3/44 8518 /proc/meminfo: memFree=699208/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=1.58 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 16225 3 18 0 0 150 8 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=23760 CPUtime=0.06 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 6717 0 19 0 5 1 0 0 18 0 1 0 878672174 24330240 5541 1283457024 134512640 136223643 4287118528 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 5940 5541 174 418 0 5520 0 [pid=8517] ppid=8504 vsize=37368 CPUtime=0.98 /proc/8517/stat : 8517 (gringo) R 8504 8504 4159 34819 4229 4202496 11149 0 22 0 93 5 0 0 18 0 1 0 878672174 38264832 7232 1283457024 134512640 136959103 4289463344 18446744073709551615 134699176 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8517/statm: 9342 7232 256 598 0 8741 0 Current children cumulated CPU time (s) 2.62 Current children cumulated vsize (KiB) 63720 [startup+6.30209 s] /proc/loadavg: 1.16 1.05 1.01 2/42 8518 /proc/meminfo: memFree=707676/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=55652 CPUtime=2.35 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 16118 0 20 0 230 5 0 0 20 0 1 0 878672174 56987648 12845 1283457024 134512640 136223643 4287118528 18446744073709551615 134650382 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 13913 12845 223 418 0 13493 0 Current children cumulated CPU time (s) 5.76 Current children cumulated vsize (KiB) 58244 [startup+12.704 s] /proc/loadavg: 1.15 1.05 1.01 2/42 8518 /proc/meminfo: memFree=707684/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=55652 CPUtime=8.74 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 16135 0 20 0 869 5 0 0 25 0 1 0 878672174 56987648 12862 1283457024 134512640 136223643 4287118528 18446744073709551615 134620413 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 13913 12862 225 418 0 13493 0 Current children cumulated CPU time (s) 12.15 Current children cumulated vsize (KiB) 58244 [startup+25.5071 s] /proc/loadavg: 1.11 1.05 1.01 2/42 8518 /proc/meminfo: memFree=689952/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=73724 CPUtime=21.53 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 20646 0 20 0 2147 6 0 0 25 0 1 0 878672174 75493376 17373 1283457024 134512640 136223643 4287118528 18446744073709551615 134630032 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 18431 17373 225 418 0 18011 0 Current children cumulated CPU time (s) 24.94 Current children cumulated vsize (KiB) 76316 [startup+51.1023 s] /proc/loadavg: 1.07 1.04 1.01 2/42 8518 /proc/meminfo: memFree=662052/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=102236 CPUtime=47.1 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 27756 0 20 0 4697 13 0 0 25 0 1 0 878672174 104689664 24483 1283457024 134512640 136223643 4287118528 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 25559 24483 225 418 0 25139 0 Current children cumulated CPU time (s) 50.51 Current children cumulated vsize (KiB) 104828 [startup+102.304 s] /proc/loadavg: 1.03 1.03 1.00 2/42 8518 /proc/meminfo: memFree=604764/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=158944 CPUtime=98.28 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 41885 0 20 0 9809 19 0 0 25 0 1 0 878672174 162758656 38612 1283457024 134512640 136223643 4287118528 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 39736 38612 225 418 0 39316 0 Current children cumulated CPU time (s) 101.69 Current children cumulated vsize (KiB) 161536 [startup+162.311 s] /proc/loadavg: 1.01 1.02 1.00 2/42 8518 /proc/meminfo: memFree=505192/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=258284 CPUtime=158.22 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 66725 0 20 0 15792 30 0 0 25 0 1 0 878672174 264482816 63452 1283457024 134512640 136223643 4287118528 18446744073709551615 134929006 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 64571 63452 225 418 0 64151 0 Current children cumulated CPU time (s) 161.63 Current children cumulated vsize (KiB) 260876 [startup+222.307 s] /proc/loadavg: 1.00 1.02 1.00 2/42 8518 /proc/meminfo: memFree=430048/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=333808 CPUtime=218.13 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 85781 0 20 0 21771 42 0 0 25 0 1 0 878672174 341819392 82267 1283457024 134512640 136223643 4287118528 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 83452 82267 225 418 0 83032 0 Current children cumulated CPU time (s) 221.54 Current children cumulated vsize (KiB) 336400 [startup+282.307 s] /proc/loadavg: 1.00 1.01 1.00 2/42 8518 /proc/meminfo: memFree=427196/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=338060 CPUtime=278.06 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 86837 0 20 0 27762 44 0 0 25 0 1 0 878672174 346173440 83323 1283457024 134512640 136223643 4287118528 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 84515 83323 225 418 0 84095 0 Current children cumulated CPU time (s) 281.47 Current children cumulated vsize (KiB) 340652 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.91 s] /proc/loadavg: 1.00 1.01 1.00 2/42 8518 /proc/meminfo: memFree=399792/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2592 CPUtime=3.41 /proc/8504/stat : 8504 (aspcud-trendy-1) S 8503 8504 4159 34819 4229 4202496 614 34691 3 40 0 0 325 16 18 0 1 0 878672162 2654208 299 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8504/statm: 648 299 253 194 0 34 0 [pid=8516] ppid=8504 vsize=363620 CPUtime=286.64 /proc/8516/stat : 8516 (clasp) R 8504 8504 4159 34819 4229 4202496 93240 0 20 0 28618 46 0 0 25 0 1 0 878672174 372346880 89726 1283457024 134512640 136223643 4287118528 18446744073709551615 134712495 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8516/statm: 90905 89726 225 418 0 90485 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 366212 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+291.014 s] /proc/loadavg: 1.00 1.01 1.00 2/42 8518 /proc/meminfo: memFree=399792/1048576 swapFree=2080288/2097144 [pid=8504] ppid=8503 vsize=2596 CPUtime=290.1 /proc/8504/stat : 8504 (aspcud-trendy-1) R 8503 8504 4159 34819 4229 4202496 844 129884 3 62 0 0 28944 66 21 0 1 0 878672162 2658304 310 1283457024 134512640 135304128 4293763264 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0 /proc/8504/statm: 649 310 263 194 0 35 0 Current children cumulated CPU time (s) 290.1 Current children cumulated vsize (KiB) 2596 Child status: 0 Real time (s): 291.016 CPU time (s): 290.102 CPU user time (s): 289.442 CPU system time (s): 0.660041 CPU usage (%): 99.6859 Max. virtual memory (cumulated for all children) (KiB): 366212 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.442 system time used= 0.660041 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 131149 page faults= 65 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2737 involuntary context switches= 5528 runsolver used 0.004 second user time and 0 second system time The end