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/rand316.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny/rand316.sarge-etch-lenny.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand316.sarge-etch-lenny.cudf.sarge-etch-lenny.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.01 1.00 5/42 15169 /proc/meminfo: memFree=654112/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2592 CPUtime=0 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 18 0 1 0 880307535 2654208 282 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/15167/statm: 648 282 237 194 0 34 0 [pid=15168] ppid=15167 vsize=2592 CPUtime=0 /proc/15168/stat : 15168 (aspcud-trendy-1) R 15167 15167 4159 34819 4229 4202560 105 0 0 0 0 0 0 0 25 0 1 0 880307535 2654208 128 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15168/statm: 648 128 82 194 0 34 0 [pid=15169] ppid=15168 vsize=2592 CPUtime=0 /proc/15169/stat : 15169 (aspcud-trendy-1) R 15168 15167 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 880307535 2654208 46 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15169/statm: 648 46 0 194 0 34 0 [startup+0.186887 s] /proc/loadavg: 1.00 1.01 1.00 5/42 15169 /proc/meminfo: memFree=654112/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=0.01 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 2215 0 0 0 0 1 0 25 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.206896 s] /proc/loadavg: 1.00 1.01 1.00 5/42 15169 /proc/meminfo: memFree=654112/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=0.01 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 2215 0 0 0 0 1 0 25 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.306907 s] /proc/loadavg: 1.00 1.01 1.00 5/42 15169 /proc/meminfo: memFree=654112/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=0.01 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 2215 0 0 0 0 1 0 25 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.707014 s] /proc/loadavg: 1.00 1.01 1.00 5/42 15169 /proc/meminfo: memFree=654112/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=0.01 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 2215 0 0 0 0 1 0 25 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+1.50715 s] /proc/loadavg: 1.00 1.01 1.00 2/44 15181 /proc/meminfo: memFree=615016/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=0.9 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 11335 0 0 0 0 88 2 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=11824 CPUtime=0.02 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 3169 0 0 0 2 0 0 0 18 0 1 0 880307536 12107776 2652 1283457024 134512640 136223643 4294889936 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 2956 2652 174 418 0 2536 0 [pid=15180] ppid=15167 vsize=18528 CPUtime=0.56 /proc/15180/stat : 15180 (gringo) R 15167 15167 4159 34819 4229 4202496 5350 0 0 0 52 4 0 0 18 0 1 0 880307536 18972672 3609 1283457024 134512640 136959103 4290305520 18446744073709551615 136227613 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15180/statm: 4632 3609 256 598 0 4031 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 32952 [startup+3.10757 s] /proc/loadavg: 1.00 1.01 1.00 3/43 15181 /proc/meminfo: memFree=596556/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=37680 CPUtime=0.85 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 10596 0 0 0 85 0 0 0 18 0 1 0 880307536 38584320 8649 1283457024 134512640 136223643 4294889936 18446744073709551615 134870708 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 9420 8649 223 418 0 9000 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 40280 [startup+6.30828 s] /proc/loadavg: 1.00 1.01 1.00 2/42 15181 /proc/meminfo: memFree=619636/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=45996 CPUtime=4.04 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 12682 0 0 0 404 0 0 0 25 0 1 0 880307536 47099904 10735 1283457024 134512640 136223643 4294889936 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 11499 10735 225 418 0 11079 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 48596 [startup+12.7098 s] /proc/loadavg: 1.00 1.01 1.00 2/42 15181 /proc/meminfo: memFree=598448/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=59328 CPUtime=10.45 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 16010 0 0 0 1041 4 0 0 25 0 1 0 880307536 60751872 14063 1283457024 134512640 136223643 4294889936 18446744073709551615 134929035 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 14832 14063 225 418 0 14412 0 Current children cumulated CPU time (s) 12.69 Current children cumulated vsize (KiB) 61928 [startup+25.5029 s] /proc/loadavg: 1.00 1.00 1.00 2/42 15181 /proc/meminfo: memFree=560132/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=97608 CPUtime=23.23 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 25586 0 0 0 2317 6 0 0 25 0 1 0 880307536 99950592 23639 1283457024 134512640 136223643 4294889936 18446744073709551615 134711766 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 24402 23639 225 418 0 23982 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 100208 [startup+51.11 s] /proc/loadavg: 1.00 1.00 1.00 2/42 15181 /proc/meminfo: memFree=484988/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=172760 CPUtime=48.82 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 44331 0 0 0 4868 14 0 0 25 0 1 0 880307536 176906240 42384 1283457024 134512640 136223643 4294889936 18446744073709551615 134929248 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 43190 42384 225 418 0 42770 0 Current children cumulated CPU time (s) 51.06 Current children cumulated vsize (KiB) 175360 [startup+102.303 s] /proc/loadavg: 1.00 1.00 1.00 2/42 15181 /proc/meminfo: memFree=433652/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=223880 CPUtime=99.96 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 57132 0 0 0 9978 18 0 0 25 0 1 0 880307536 229253120 55185 1283457024 134512640 136223643 4294889936 18446744073709551615 134711229 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 55970 55185 225 418 0 55550 0 Current children cumulated CPU time (s) 102.2 Current children cumulated vsize (KiB) 226480 [startup+162.305 s] /proc/loadavg: 1.00 1.00 1.00 2/42 15181 /proc/meminfo: memFree=365204/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=292280 CPUtime=159.97 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 74186 0 0 0 15967 30 0 0 25 0 1 0 880307536 299294720 72239 1283457024 134512640 136223643 4294889936 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 73070 72239 225 418 0 72650 0 Current children cumulated CPU time (s) 162.21 Current children cumulated vsize (KiB) 294880 [startup+222.312 s] /proc/loadavg: 1.00 1.00 1.00 2/42 15181 /proc/meminfo: memFree=337428/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=319976 CPUtime=219.89 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 81240 0 0 0 21955 34 0 0 25 0 1 0 880307536 327655424 79188 1283457024 134512640 136223643 4294889936 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 79994 79188 225 418 0 79574 0 Current children cumulated CPU time (s) 222.13 Current children cumulated vsize (KiB) 322576 [startup+282.31 s] /proc/loadavg: 1.00 1.00 1.00 2/42 15181 /proc/meminfo: memFree=337428/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=319976 CPUtime=279.84 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 81240 0 0 0 27950 34 0 0 25 0 1 0 880307536 327655424 79188 1283457024 134512640 136223643 4294889936 18446744073709551615 134940658 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 79994 79188 225 418 0 79574 0 Current children cumulated CPU time (s) 282.08 Current children cumulated vsize (KiB) 322576 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.313 s] /proc/loadavg: 1.00 1.00 1.00 2/42 15181 /proc/meminfo: memFree=337428/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=319976 CPUtime=287.84 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 81240 0 0 0 28749 35 0 0 25 0 1 0 880307536 327655424 79188 1283457024 134512640 136223643 4294889936 18446744073709551615 134928869 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 79994 79188 225 418 0 79574 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 322576 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+290.313 s] /proc/loadavg: 1.00 1.00 1.00 2/42 15181 /proc/meminfo: memFree=337428/1048576 swapFree=2080272/2097144 [pid=15167] ppid=15166 vsize=2600 CPUtime=2.24 /proc/15167/stat : 15167 (aspcud-trendy-1) S 15166 15167 4159 34819 4229 4202496 621 24325 0 0 0 0 213 11 18 0 1 0 880307535 2662400 300 1283457024 134512640 135304128 4286616080 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15167/statm: 650 300 253 194 0 36 0 [pid=15179] ppid=15167 vsize=319976 CPUtime=287.84 /proc/15179/stat : 15179 (clasp) R 15167 15167 4159 34819 4229 4202496 81240 0 0 0 28749 35 0 0 25 0 1 0 880307536 327655424 79188 1283457024 134512640 136223643 4294889936 18446744073709551615 134928869 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15179/statm: 79994 79188 225 418 0 79574 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 322576 Child status: 0 Real time (s): 290.352 CPU time (s): 290.126 CPU user time (s): 289.63 CPU system time (s): 0.496031 CPU usage (%): 99.9222 Max. virtual memory (cumulated for all children) (KiB): 322576 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.63 system time used= 0.496031 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 108795 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1316 involuntary context switches= 4358 runsolver used 0 second user time and 0 second system time The end