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/rand753.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand753.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand753.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.26 1.14 1.09 3/46 23079
/proc/meminfo: memFree=489460/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2588 CPUtime=0
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 882141341 2650112 281 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/23076/statm: 647 281 237 194 0 33 0
[pid=23077] ppid=23076 vsize=2588 CPUtime=0
/proc/23077/stat : 23077 (aspcud-trendy-1) S 23076 23076 4159 34819 4229 4202560 114 0 0 0 0 0 0 0 25 0 1 0 882141342 2650112 128 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/23077/statm: 647 128 83 194 0 33 0
[pid=23078] ppid=23077 vsize=2588 CPUtime=0
/proc/23078/stat : 23078 (aspcud-trendy-1) R 23077 23076 4159 34819 4229 4202560 126 0 0 0 0 0 0 0 25 0 1 0 882141342 2650112 148 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/23078/statm: 647 148 103 194 0 33 0
[pid=23079] ppid=23078 vsize=2588 CPUtime=0
/proc/23079/stat : 23079 (aspcud-trendy-1) R 23078 23076 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 882141342 2650112 45 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/23079/statm: 647 45 0 194 0 33 0

[startup+0.129863 s]
/proc/loadavg: 1.26 1.14 1.09 3/46 23079
/proc/meminfo: memFree=489460/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=0.01
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 618 2217 0 0 0 0 0 1 25 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.209889 s]
/proc/loadavg: 1.26 1.14 1.09 3/46 23079
/proc/meminfo: memFree=489460/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=0.01
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 618 2217 0 0 0 0 0 1 25 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.309906 s]
/proc/loadavg: 1.26 1.14 1.09 3/46 23079
/proc/meminfo: memFree=489460/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=0.01
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 618 2217 0 0 0 0 0 1 25 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.709983 s]
/proc/loadavg: 1.26 1.14 1.09 3/46 23079
/proc/meminfo: memFree=489460/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=0.01
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 618 2217 0 0 0 0 0 1 25 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.51016 s]
/proc/loadavg: 1.26 1.14 1.09 2/47 23090
/proc/meminfo: memFree=447292/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=0.01
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 618 2217 0 0 0 0 0 1 25 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=5516 CPUtime=0.02
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 1298 0 0 0 2 0 0 0 18 0 1 0 882141343 5648384 1085 1283457024 134512640 136223643 4288836624 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 1379 1085 174 418 0 959 0
[pid=23089] ppid=23076 vsize=8008 CPUtime=0.16
/proc/23089/stat : 23089 (gringo) R 23076 23076 4159 34819 4229 4202496 1949 0 0 0 16 0 0 0 18 0 1 0 882141343 8200192 1349 1283457024 134512640 136959103 4287865760 18446744073709551615 134620050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23089/statm: 2002 1349 247 598 0 1401 0
[pid=23090] ppid=23076 vsize=43444 CPUtime=1.3
/proc/23090/stat : 23090 (cudf2lp) R 23076 23076 4159 34819 4229 4202496 14020 0 0 0 126 4 0 0 25 0 1 0 882141343 44486656 10656 1283457024 134512640 135749571 4291178208 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/23090/statm: 10861 10656 129 302 0 10557 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 59564

[startup+3.11056 s]
/proc/loadavg: 1.26 1.14 1.09 3/47 23090
/proc/meminfo: memFree=418152/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=1.57
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 16241 0 0 0 0 149 8 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=32724 CPUtime=0.19
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 9248 0 0 0 15 4 0 0 18 0 1 0 882141343 33509376 7749 1283457024 134512640 136223643 4288836624 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 8181 7749 174 418 0 7761 0
[pid=23089] ppid=23076 vsize=53288 CPUtime=1.33
/proc/23089/stat : 23089 (gringo) R 23076 23076 4159 34819 4229 4202496 15583 0 0 0 130 3 0 0 18 0 1 0 882141343 54566912 10872 1283457024 134512640 136959103 4287865760 18446744073709551615 135865834 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23089/statm: 13322 10872 256 598 0 12721 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 88608

[startup+6.31152 s]
/proc/loadavg: 1.32 1.16 1.09 2/45 23090
/proc/meminfo: memFree=437404/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=55616 CPUtime=2.85
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 15985 0 0 0 280 5 0 0 22 0 1 0 882141343 56950784 12858 1283457024 134512640 136223643 4288836624 18446744073709551615 134870708 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 13904 12858 222 418 0 13484 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 58212

[startup+12.7138 s]
/proc/loadavg: 1.29 1.15 1.09 2/45 23090
/proc/meminfo: memFree=438148/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=55616 CPUtime=9.24
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 15988 0 0 0 918 6 0 0 25 0 1 0 882141343 56950784 12861 1283457024 134512640 136223643 4288836624 18446744073709551615 134929390 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 13904 12861 225 418 0 13484 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 58212

[startup+25.5072 s]
/proc/loadavg: 1.23 1.15 1.09 2/45 23090
/proc/meminfo: memFree=400824/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=93448 CPUtime=22.03
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 25440 0 0 0 2194 9 0 0 25 0 1 0 882141343 95690752 22313 1283457024 134512640 136223643 4288836624 18446744073709551615 134631228 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 23362 22313 225 418 0 22942 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 96044

[startup+51.1127 s]
/proc/loadavg: 1.15 1.13 1.09 2/45 23090
/proc/meminfo: memFree=392888/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=101236 CPUtime=47.62
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 27395 0 0 0 4749 13 0 0 25 0 1 0 882141343 103665664 24268 1283457024 134512640 136223643 4288836624 18446744073709551615 134603543 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 25309 24268 225 418 0 24889 0
Current children cumulated CPU time (s) 51.07
Current children cumulated vsize (KiB) 103832

[startup+102.305 s]
/proc/loadavg: 1.06 1.11 1.08 2/45 23090
/proc/meminfo: memFree=361268/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=132376 CPUtime=98.74
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 35580 0 0 0 9856 18 0 0 25 0 1 0 882141343 135553024 32036 1283457024 134512640 136223643 4288836624 18446744073709551615 134940571 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 33094 32036 225 418 0 32674 0
Current children cumulated CPU time (s) 102.19
Current children cumulated vsize (KiB) 134972

[startup+162.312 s]
/proc/loadavg: 1.02 1.09 1.08 2/45 23090
/proc/meminfo: memFree=250784/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=243600 CPUtime=158.7
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 63344 0 0 0 15845 25 0 0 25 0 1 0 882141343 249446400 59800 1283457024 134512640 136223643 4288836624 18446744073709551615 134712523 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 60900 59800 225 418 0 60480 0
Current children cumulated CPU time (s) 162.15
Current children cumulated vsize (KiB) 246196

[startup+222.309 s]
/proc/loadavg: 1.01 1.07 1.07 2/45 23090
/proc/meminfo: memFree=197588/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=296284 CPUtime=218.62
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 76539 0 0 0 21833 29 0 0 25 0 1 0 882141343 303394816 72995 1283457024 134512640 136223643 4288836624 18446744073709551615 134940571 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 74071 72995 225 418 0 73651 0
Current children cumulated CPU time (s) 222.07
Current children cumulated vsize (KiB) 298880

[startup+282.306 s]
/proc/loadavg: 1.00 1.05 1.06 2/45 23090
/proc/meminfo: memFree=177376/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=316588 CPUtime=278.59
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 81961 0 0 0 27828 31 0 0 25 0 1 0 882141343 324186112 78027 1283457024 134512640 136223643 4288836624 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 79147 78027 225 418 0 78727 0
Current children cumulated CPU time (s) 282.04
Current children cumulated vsize (KiB) 319184



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.309 s]
/proc/loadavg: 1.00 1.05 1.06 2/45 23090
/proc/meminfo: memFree=177376/1048576 swapFree=2077724/2097144
[pid=23076] ppid=23075 vsize=2596 CPUtime=3.45
/proc/23076/stat : 23076 (aspcud-trendy-1) S 23075 23076 4159 34819 4229 4202496 619 34781 0 0 0 0 332 13 18 0 1 0 882141341 2658304 299 1283457024 134512640 135304128 4290850288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23076/statm: 649 299 253 194 0 35 0
[pid=23088] ppid=23076 vsize=316588 CPUtime=286.56
/proc/23088/stat : 23088 (clasp) R 23076 23076 4159 34819 4229 4202496 81961 0 0 0 28625 31 0 0 25 0 1 0 882141343 324186112 78027 1283457024 134512640 136223643 4288836624 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23088/statm: 79147 78027 225 418 0 78727 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 319184

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.347
CPU time (s): 290.05
CPU user time (s): 289.574
CPU system time (s): 0.476029
CPU usage (%): 99.8978
Max. virtual memory (cumulated for all children) (KiB): 319184

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.574
system time used= 0.476029
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 119979
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= 2713
involuntary context switches= 5571

runsolver used 0 second user time and 0 second system time

The end