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/201012061533/aspcud-paranoid-1.3/rand165.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./aspcud-paranoid-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand165.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012061533/aspcud-paranoid-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.28 1.16 1.09 1/45 6518 /proc/meminfo: memFree=919740/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=3024 CPUtime=0 /proc/6518/stat : 6518 (runsolver) D 6517 6518 2059 34821 2220 4202560 73 0 0 0 0 0 0 0 25 0 1 0 874775307 3096576 94 1283457024 134512640 134586868 4291896832 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/6518/statm: 756 94 62 19 0 54 0 [startup+0.181025 s] /proc/loadavg: 1.28 1.16 1.09 1/45 6518 /proc/meminfo: memFree=919740/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=0 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 658 2929 0 3 0 0 0 0 25 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.209024 s] /proc/loadavg: 1.28 1.16 1.09 1/45 6518 /proc/meminfo: memFree=919740/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=0 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 658 2929 0 3 0 0 0 0 25 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.309047 s] /proc/loadavg: 1.28 1.16 1.09 1/45 6518 /proc/meminfo: memFree=919740/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=0 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 658 2929 0 3 0 0 0 0 25 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.709109 s] /proc/loadavg: 1.28 1.16 1.09 1/45 6518 /proc/meminfo: memFree=919740/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=0 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 658 2929 0 3 0 0 0 0 25 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.50924 s] /proc/loadavg: 1.28 1.16 1.09 2/49 6535 /proc/meminfo: memFree=881368/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=0 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 658 2929 0 3 0 0 0 0 25 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=3568 CPUtime=0 /proc/6533/stat : 6533 (clasp) S 6518 6518 2059 34821 2220 4202496 736 0 18 0 0 0 0 0 18 0 1 0 874775313 3653632 622 1283457024 134512640 136223643 4287607520 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/6533/statm: 892 622 174 418 0 472 0 [pid=6534] ppid=6518 vsize=4924 CPUtime=0.09 /proc/6534/stat : 6534 (gringo) R 6518 6518 2059 34821 2220 4202496 1014 0 22 0 9 0 0 0 18 0 1 0 874775313 5042176 759 1283457024 134512640 136959103 4293681440 18446744073709551615 134785587 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6534/statm: 1231 759 247 598 0 630 0 [pid=6535] ppid=6518 vsize=43444 CPUtime=1.21 /proc/6535/stat : 6535 (cudf2lp) R 6518 6518 2059 34821 2220 4202496 14008 0 14 0 119 2 0 0 25 0 1 0 874775313 44486656 10656 1283457024 134512640 135749571 4291788656 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/6535/statm: 10861 10656 129 302 0 10557 0 Current children cumulated CPU time (s) 1.3 Current children cumulated vsize (KiB) 54536 [startup+3.10951 s] /proc/loadavg: 1.28 1.16 1.09 3/48 6535 /proc/meminfo: memFree=891496/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=32860 CPUtime=0.28 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 7829 0 19 0 25 3 0 0 18 0 1 0 874775313 33648640 6855 1283457024 134512640 136223643 4287607520 18446744073709551615 135599134 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 8215 6855 187 418 0 7795 0 Current children cumulated CPU time (s) 2.91 Current children cumulated vsize (KiB) 35460 [startup+6.30997 s] /proc/loadavg: 1.26 1.16 1.09 2/47 6535 /proc/meminfo: memFree=882028/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=35700 CPUtime=3.48 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 10128 0 19 0 345 3 0 0 25 0 1 0 874775313 36556800 8187 1283457024 134512640 136223643 4287607520 18446744073709551615 134711227 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 8925 8187 225 418 0 8505 0 Current children cumulated CPU time (s) 6.11 Current children cumulated vsize (KiB) 38300 [startup+12.7116 s] /proc/loadavg: 1.24 1.15 1.09 2/47 6535 /proc/meminfo: memFree=876696/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=44080 CPUtime=9.88 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 12244 0 19 0 984 4 0 0 25 0 1 0 874775313 45137920 10303 1283457024 134512640 136223643 4287607520 18446744073709551615 134712456 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 11020 10303 225 418 0 10600 0 Current children cumulated CPU time (s) 12.51 Current children cumulated vsize (KiB) 46680 [startup+25.5042 s] /proc/loadavg: 1.18 1.15 1.09 2/47 6535 /proc/meminfo: memFree=868636/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=49492 CPUtime=22.65 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 13586 0 19 0 2261 4 0 0 25 0 1 0 874775313 50679808 11645 1283457024 134512640 136223643 4287607520 18446744073709551615 134711220 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 12373 11645 225 418 0 11953 0 Current children cumulated CPU time (s) 25.28 Current children cumulated vsize (KiB) 52092 [startup+51.1102 s] /proc/loadavg: 1.12 1.13 1.09 2/47 6535 /proc/meminfo: memFree=853384/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=64048 CPUtime=48.23 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 17613 0 19 0 4817 6 0 0 25 0 1 0 874775313 65585152 15299 1283457024 134512640 136223643 4287607520 18446744073709551615 134611253 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 16012 15299 225 418 0 15592 0 Current children cumulated CPU time (s) 50.86 Current children cumulated vsize (KiB) 66648 [startup+102.314 s] /proc/loadavg: 1.05 1.11 1.08 3/47 6535 /proc/meminfo: memFree=769684/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=148352 CPUtime=99.04 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 38722 0 19 0 9884 20 0 0 25 0 1 0 874775313 151912448 36303 1283457024 134512640 136223643 4287607520 18446744073709551615 134929248 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 37088 36303 225 418 0 36668 0 Current children cumulated CPU time (s) 101.67 Current children cumulated vsize (KiB) 150952 [startup+162.309 s] /proc/loadavg: 1.02 1.09 1.08 2/47 6535 /proc/meminfo: memFree=767452/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=150388 CPUtime=158.99 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 39246 0 19 0 15877 22 0 0 25 0 1 0 874775313 153997312 36827 1283457024 134512640 136223643 4287607520 18446744073709551615 134940541 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 37597 36827 225 418 0 37177 0 Current children cumulated CPU time (s) 161.62 Current children cumulated vsize (KiB) 152988 [startup+222.305 s] /proc/loadavg: 1.00 1.07 1.07 2/47 6535 /proc/meminfo: memFree=766088/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=151840 CPUtime=218.94 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 39606 0 19 0 21872 22 0 0 25 0 1 0 874775313 155484160 37187 1283457024 134512640 136223643 4287607520 18446744073709551615 134928913 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 37960 37187 225 418 0 37540 0 Current children cumulated CPU time (s) 221.57 Current children cumulated vsize (KiB) 154440 [startup+282.304 s] /proc/loadavg: 1.00 1.05 1.06 2/47 6535 /proc/meminfo: memFree=766584/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=150572 CPUtime=278.85 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 39732 0 19 0 27861 24 0 0 25 0 1 0 874775313 154185728 36902 1283457024 134512640 136223643 4287607520 18446744073709551615 134924244 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 37643 36902 225 418 0 37223 0 Current children cumulated CPU time (s) 281.48 Current children cumulated vsize (KiB) 153172 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.906 s] /proc/loadavg: 1.00 1.05 1.06 2/47 6535 /proc/meminfo: memFree=766212/1048576 swapFree=2078740/2097144 [pid=6518] ppid=6517 vsize=2600 CPUtime=2.63 /proc/6518/stat : 6518 (aspcud-paranoid) S 6517 6518 2059 34821 2220 4202496 659 29658 0 40 0 0 255 8 18 0 1 0 874775307 2662400 301 1283457024 134512640 135304128 4292509568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/6518/statm: 650 301 253 194 0 36 0 [pid=6533] ppid=6518 vsize=151496 CPUtime=287.44 /proc/6533/stat : 6533 (clasp) R 6518 6518 2059 34821 2220 4202496 39960 0 19 0 28720 24 0 0 25 0 1 0 874775313 155131904 37130 1283457024 134512640 136223643 4287607520 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/6533/statm: 37874 37130 225 418 0 37454 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 154096 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): 290.948 CPU time (s): 290.094 CPU user time (s): 289.754 CPU system time (s): 0.340021 CPU usage (%): 99.7064 Max. virtual memory (cumulated for all children) (KiB): 154440 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.754 system time used= 0.340021 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 72883 page faults= 60 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1425 involuntary context switches= 4540 runsolver used 0.004 second user time and 0 second system time The end