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/rand165.sarge-etch.cudf.sarge-etch.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch/rand165.sarge-etch.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand165.sarge-etch.cudf.sarge-etch.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.02 0.97 0.91 3/39 9903
/proc/meminfo: memFree=69432/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0
/proc/9902/stat : 9902 (cudf2pbo4trendy) R 9901 9902 9023 34817 9081 4202496 364 0 0 0 0 0 0 0 25 0 1 0 892654208 2629632 277 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/9902/statm: 642 277 238 194 0 28 0
[pid=9903] ppid=9902 vsize=2568 CPUtime=0
/proc/9903/stat : 9903 (cudf2pbo4trendy) R 9902 9902 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 892654208 2629632 39 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/9903/statm: 642 39 0 194 0 28 0

[startup+0.163686 s]
/proc/loadavg: 1.02 0.97 0.91 3/39 9903
/proc/meminfo: memFree=69432/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892654208 2629632 277 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 277 238 194 0 28 0
[pid=9903] ppid=9902 vsize=8396 CPUtime=0.16
/proc/9903/stat : 9903 (cudf_msu32) R 9902 9902 9023 34817 9081 4202496 1900 0 0 0 16 0 0 0 25 0 1 0 892654208 8597504 1793 1283457024 134512640 136125367 4287259440 18446744073709551615 135535017 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9903/statm: 2099 1793 142 394 0 1703 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 10964

[startup+0.213707 s]
/proc/loadavg: 1.02 0.97 0.91 3/39 9903
/proc/meminfo: memFree=69432/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892654208 2629632 277 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 277 238 194 0 28 0
[pid=9903] ppid=9902 vsize=10000 CPUtime=0.2
/proc/9903/stat : 9903 (cudf_msu32) R 9902 9902 9023 34817 9081 4202496 2323 0 0 0 20 0 0 0 25 0 1 0 892654208 10240000 2216 1283457024 134512640 136125367 4287259440 18446744073709551615 135594526 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9903/statm: 2500 2216 142 394 0 2104 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12568

[startup+0.303738 s]
/proc/loadavg: 1.02 0.97 0.91 3/39 9903
/proc/meminfo: memFree=69432/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892654208 2629632 277 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 277 238 194 0 28 0
[pid=9903] ppid=9902 vsize=13232 CPUtime=0.3
/proc/9903/stat : 9903 (cudf_msu32) R 9902 9902 9023 34817 9081 4202496 3120 0 0 0 30 0 0 0 25 0 1 0 892654208 13549568 3013 1283457024 134512640 136125367 4287259440 18446744073709551615 134728322 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9903/statm: 3308 3013 143 394 0 2912 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15800

[startup+0.703809 s]
/proc/loadavg: 1.02 0.97 0.91 3/39 9903
/proc/meminfo: memFree=69432/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892654208 2629632 277 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 277 238 194 0 28 0
[pid=9903] ppid=9902 vsize=23644 CPUtime=0.68
/proc/9903/stat : 9903 (cudf_msu32) R 9902 9902 9023 34817 9081 4202496 5729 0 0 0 62 6 0 0 25 0 1 0 892654208 24211456 5622 1283457024 134512640 136125367 4287259440 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9903/statm: 5911 5622 165 394 0 5515 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 26212

[startup+1.50394 s]
/proc/loadavg: 1.01 0.97 0.91 2/40 9905
/proc/meminfo: memFree=58996/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=11864 CPUtime=0.66
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 3224 0 0 0 46 20 0 0 24 0 1 0 892654292 12148736 2615 1283457024 134512640 135887319 4288715920 18446744073709551615 134614999 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 2966 2615 138 336 0 2628 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 14432

[startup+3.10436 s]
/proc/loadavg: 1.01 0.97 0.91 2/40 9905
/proc/meminfo: memFree=53416/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=21420 CPUtime=2.23
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 7405 0 0 0 171 52 0 0 25 0 1 0 892654292 21934080 5032 1283457024 134512640 135887319 4288715920 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 5355 5032 144 336 0 5017 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 23988

[startup+6.30514 s]
/proc/loadavg: 1.01 0.97 0.91 2/40 9905
/proc/meminfo: memFree=48952/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=21420 CPUtime=5.43
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 7405 0 0 0 491 52 0 0 25 0 1 0 892654292 21934080 5032 1283457024 134512640 135887319 4288715920 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 5355 5032 144 336 0 5017 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 23988

[startup+12.7071 s]
/proc/loadavg: 1.01 0.97 0.91 2/40 9905
/proc/meminfo: memFree=48952/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=21420 CPUtime=11.83
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 7423 0 0 0 1129 54 0 0 25 0 1 0 892654292 21934080 5047 1283457024 134512640 135887319 4288715920 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 5355 5047 144 336 0 5017 0
Current children cumulated CPU time (s) 12.65
Current children cumulated vsize (KiB) 23988

[startup+25.5095 s]
/proc/loadavg: 1.01 0.97 0.91 2/40 9905
/proc/meminfo: memFree=48952/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=21420 CPUtime=24.64
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 7423 0 0 0 2406 58 0 0 25 0 1 0 892654292 21934080 5047 1283457024 134512640 135887319 4288715920 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 5355 5047 144 336 0 5017 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 23988

[startup+51.1067 s]
/proc/loadavg: 1.00 0.97 0.91 2/40 9905
/proc/meminfo: memFree=48084/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=22352 CPUtime=50.2
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 7670 0 0 0 4957 63 0 0 25 0 1 0 892654292 22888448 5273 1283457024 134512640 135887319 4288715920 18446744073709551615 134603579 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 5588 5273 144 336 0 5250 0
Current children cumulated CPU time (s) 51.02
Current children cumulated vsize (KiB) 24920

[startup+102.306 s]
/proc/loadavg: 1.00 0.97 0.91 2/40 9905
/proc/meminfo: memFree=45356/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=25016 CPUtime=101.38
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 8414 0 0 0 10068 70 0 0 25 0 1 0 892654292 25616384 5906 1283457024 134512640 135887319 4288715920 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 6254 5906 144 336 0 5916 0
Current children cumulated CPU time (s) 102.2
Current children cumulated vsize (KiB) 27584

[startup+162.31 s]
/proc/loadavg: 1.00 0.97 0.91 2/40 9905
/proc/meminfo: memFree=42256/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=28004 CPUtime=161.34
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 9315 0 0 0 16057 77 0 0 25 0 1 0 892654292 28676096 6677 1283457024 134512640 135887319 4288715920 18446744073709551615 134604720 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 7001 6677 144 336 0 6663 0
Current children cumulated CPU time (s) 162.16
Current children cumulated vsize (KiB) 30572

[startup+222.303 s]
/proc/loadavg: 1.00 0.97 0.91 2/40 9905
/proc/meminfo: memFree=40520/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=29612 CPUtime=221.27
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 9789 0 0 0 22033 94 0 0 25 0 1 0 892654292 30322688 7085 1283457024 134512640 135887319 4288715920 18446744073709551615 134603644 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 7403 7085 144 336 0 7065 0
Current children cumulated CPU time (s) 222.09
Current children cumulated vsize (KiB) 32180

[startup+282.307 s]
/proc/loadavg: 1.00 0.97 0.91 2/40 9905
/proc/meminfo: memFree=40396/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=29612 CPUtime=281.19
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 9790 0 0 0 28019 100 0 0 25 0 1 0 892654292 30322688 7086 1283457024 134512640 135887319 4288715920 18446744073709551615 134624367 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 7403 7086 144 336 0 7065 0
Current children cumulated CPU time (s) 282.01
Current children cumulated vsize (KiB) 32180



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.309 s]
/proc/loadavg: 1.00 0.97 0.91 2/40 9905
/proc/meminfo: memFree=40396/1048576 swapFree=2095372/2097144
[pid=9902] ppid=9901 vsize=2568 CPUtime=0.82
/proc/9902/stat : 9902 (cudf2pbo4trendy) S 9901 9902 9023 34817 9081 4202496 400 5731 0 0 0 0 71 11 18 0 1 0 892654208 2629632 280 1283457024 134512640 135304128 4291145328 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9902/statm: 642 280 241 194 0 28 0
[pid=9905] ppid=9902 vsize=29612 CPUtime=289.18
/proc/9905/stat : 9905 (bmo-pblex32) R 9902 9902 9023 34817 9081 4202496 9790 0 0 0 28818 100 0 0 25 0 1 0 892654292 30322688 7086 1283457024 134512640 135887319 4288715920 18446744073709551615 134603644 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9905/statm: 7403 7086 144 336 0 7065 0
Current children cumulated CPU time (s) 290
Current children cumulated vsize (KiB) 32180

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.361
CPU time (s): 290.062
CPU user time (s): 288.946
CPU system time (s): 1.11607
CPU usage (%): 99.8972
Max. virtual memory (cumulated for all children) (KiB): 32180

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 288.946
system time used= 1.11607
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 17572
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= 8
involuntary context switches= 4804

runsolver used 0 second user time and 0.012 second system time

The end