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/201012081719/cudf2pbo4trendy-1.0/rand986.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny/rand986.sarge-etch-lenny.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand986.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: 0.84 0.94 0.90 4/35 13043
/proc/meminfo: memFree=72800/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=0
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 894376781 2637824 278 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 278 238 194 0 30 0
[pid=13043] ppid=13042 vsize=2052 CPUtime=0.01
/proc/13043/stat : 13043 (cudf_msu32) R 13042 13042 9023 34817 9081 4202496 305 0 0 0 1 0 0 0 25 0 1 0 894376781 2101248 197 1283457024 134512640 136125367 4286567024 18446744073709551615 134738344 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13043/statm: 513 197 141 394 0 117 0

[startup+0.185594 s]
/proc/loadavg: 0.84 0.94 0.90 4/35 13043
/proc/meminfo: memFree=72800/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=0
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 894376781 2637824 278 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 278 238 194 0 30 0
[pid=13043] ppid=13042 vsize=9280 CPUtime=0.18
/proc/13043/stat : 13043 (cudf_msu32) R 13042 13042 9023 34817 9081 4202496 2137 0 0 0 16 2 0 0 25 0 1 0 894376781 9502720 2029 1283457024 134512640 136125367 4286567024 18446744073709551615 135528938 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13043/statm: 2320 2029 142 394 0 1924 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 11856

[startup+0.205602 s]
/proc/loadavg: 0.84 0.94 0.90 4/35 13043
/proc/meminfo: memFree=72800/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=0
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 894376781 2637824 278 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 278 238 194 0 30 0
[pid=13043] ppid=13042 vsize=10000 CPUtime=0.2
/proc/13043/stat : 13043 (cudf_msu32) R 13042 13042 9023 34817 9081 4202496 2303 0 0 0 18 2 0 0 25 0 1 0 894376781 10240000 2195 1283457024 134512640 136125367 4286567024 18446744073709551615 134717896 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13043/statm: 2500 2195 142 394 0 2104 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12576

[startup+0.305608 s]
/proc/loadavg: 0.84 0.94 0.90 4/35 13043
/proc/meminfo: memFree=72800/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=0
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 894376781 2637824 278 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 278 238 194 0 30 0
[pid=13043] ppid=13042 vsize=13364 CPUtime=0.3
/proc/13043/stat : 13043 (cudf_msu32) R 13042 13042 9023 34817 9081 4202496 3152 0 0 0 28 2 0 0 25 0 1 0 894376781 13684736 3044 1283457024 134512640 136125367 4286567024 18446744073709551615 134717966 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13043/statm: 3341 3044 143 394 0 2945 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15940

[startup+0.705657 s]
/proc/loadavg: 0.84 0.94 0.90 4/35 13043
/proc/meminfo: memFree=72800/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=0
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 894376781 2637824 278 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 278 238 194 0 30 0
[pid=13043] ppid=13042 vsize=24936 CPUtime=0.71
/proc/13043/stat : 13043 (cudf_msu32) R 13042 13042 9023 34817 9081 4202496 6052 0 0 0 64 7 0 0 25 0 1 0 894376781 25534464 5944 1283457024 134512640 136125367 4286567024 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13043/statm: 6234 5944 153 394 0 5838 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 27512

[startup+1.50576 s]
/proc/loadavg: 0.84 0.94 0.90 2/36 13044
/proc/meminfo: memFree=36572/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 2576

[startup+3.11108 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 13045
/proc/meminfo: memFree=53560/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=18916 CPUtime=1.52
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 5095 0 0 0 108 44 0 0 25 0 1 0 894376928 19369984 4365 1283457024 134512640 135887319 4286759600 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 4729 4365 138 336 0 4391 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 21492

[startup+6.31199 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 13045
/proc/meminfo: memFree=47244/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=24888 CPUtime=4.72
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 7423 0 0 0 392 80 0 0 25 0 1 0 894376928 25485312 5853 1283457024 134512640 135887319 4286759600 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 6222 5853 144 336 0 5884 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 27464

[startup+12.7035 s]
/proc/loadavg: 0.88 0.94 0.90 2/36 13045
/proc/meminfo: memFree=42284/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=29852 CPUtime=11.11
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 9695 0 0 0 1015 96 0 0 25 0 1 0 894376928 30568448 7106 1283457024 134512640 135887319 4286759600 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 7463 7106 144 336 0 7125 0
Current children cumulated CPU time (s) 12.57
Current children cumulated vsize (KiB) 32428

[startup+25.5088 s]
/proc/loadavg: 0.89 0.94 0.90 2/36 13045
/proc/meminfo: memFree=37448/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=34184 CPUtime=23.89
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 11634 0 0 0 2259 130 0 0 25 0 1 0 894376928 35004416 8225 1283457024 134512640 135887319 4286759600 18446744073709551615 134598528 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 8546 8225 144 336 0 8208 0
Current children cumulated CPU time (s) 25.35
Current children cumulated vsize (KiB) 36760

[startup+51.1146 s]
/proc/loadavg: 0.93 0.94 0.90 2/36 13045
/proc/meminfo: memFree=33728/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=38452 CPUtime=49.48
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 12770 0 0 0 4764 184 0 0 25 0 1 0 894376928 39374848 9277 1283457024 134512640 135887319 4286759600 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 9613 9277 144 336 0 9275 0
Current children cumulated CPU time (s) 50.94
Current children cumulated vsize (KiB) 41028

[startup+102.314 s]
/proc/loadavg: 0.97 0.95 0.91 2/36 13045
/proc/meminfo: memFree=31992/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=40044 CPUtime=100.71
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 13187 0 0 0 9885 186 0 0 25 0 1 0 894376928 41005056 9678 1283457024 134512640 135887319 4286759600 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 10011 9678 144 336 0 9673 0
Current children cumulated CPU time (s) 102.17
Current children cumulated vsize (KiB) 42620

[startup+162.308 s]
/proc/loadavg: 0.99 0.95 0.91 2/36 13045
/proc/meminfo: memFree=31000/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=40968 CPUtime=160.66
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 13453 0 0 0 15876 190 0 0 25 0 1 0 894376928 41951232 9921 1283457024 134512640 135887319 4286759600 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 10242 9921 144 336 0 9904 0
Current children cumulated CPU time (s) 162.12
Current children cumulated vsize (KiB) 43544

[startup+222.311 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 13045
/proc/meminfo: memFree=30380/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=41628 CPUtime=220.6
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 13611 0 0 0 21870 190 0 0 25 0 1 0 894376928 42627072 10074 1283457024 134512640 135887319 4286759600 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 10407 10074 144 336 0 10069 0
Current children cumulated CPU time (s) 222.06
Current children cumulated vsize (KiB) 44204

[startup+282.303 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 13045
/proc/meminfo: memFree=29512/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=42624 CPUtime=280.56
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 13870 0 0 0 27866 190 0 0 25 0 1 0 894376928 43646976 10305 1283457024 134512640 135887319 4286759600 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 10656 10305 144 336 0 10318 0
Current children cumulated CPU time (s) 282.02
Current children cumulated vsize (KiB) 45200



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.305 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 13045
/proc/meminfo: memFree=29388/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=42624 CPUtime=288.56
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 13892 0 0 0 28665 191 0 0 25 0 1 0 894376928 43646976 10327 1283457024 134512640 135887319 4286759600 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 10656 10327 144 336 0 10318 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 45200

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.305 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 13045
/proc/meminfo: memFree=29388/1048576 swapFree=2095372/2097144
[pid=13042] ppid=13041 vsize=2576 CPUtime=1.46
/proc/13042/stat : 13042 (cudf2pbo4trendy) S 13041 13042 9023 34817 9081 4202496 403 9353 0 0 0 0 110 36 20 0 1 0 894376781 2637824 281 1283457024 134512640 135304128 4287124096 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13042/statm: 644 281 241 194 0 30 0
[pid=13045] ppid=13042 vsize=42624 CPUtime=288.56
/proc/13045/stat : 13045 (bmo-pblex32) R 13042 13042 9023 34817 9081 4202496 13892 0 0 0 28665 191 0 0 25 0 1 0 894376928 43646976 10327 1283457024 134512640 135887319 4286759600 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13045/statm: 10656 10327 144 336 0 10318 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 45200

Child status: 0
Real time (s): 290.381
CPU time (s): 290.114
CPU user time (s): 287.81
CPU system time (s): 2.30414
CPU usage (%): 99.9081
Max. virtual memory (cumulated for all children) (KiB): 45200

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 287.81
system time used= 2.30414
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25598
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= 13
involuntary context switches= 7599

runsolver used 0 second user time and 0 second system time

The end