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/cudf2pbo4paranoid-1.0/huge2.cudf.cudf_set.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/cudf_set//huge2.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/huge2.cudf.cudf_set.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.07 0.98 0.85 3/39 9560
/proc/meminfo: memFree=52180/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892395272 2637824 279 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 279 238 194 0 30 0
[pid=9560] ppid=9559 vsize=1912 CPUtime=0
/proc/9560/stat : 9560 (cudf_msu32) D 9559 9559 9023 34817 9081 4202496 264 0 0 0 0 0 0 0 18 0 1 0 892395272 1957888 156 1283457024 134512640 136125367 4293742944 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/9560/statm: 478 156 133 394 0 82 0

[startup+0.175815 s]
/proc/loadavg: 1.07 0.98 0.85 3/39 9560
/proc/meminfo: memFree=52180/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892395272 2637824 279 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 279 238 194 0 30 0
[pid=9560] ppid=9559 vsize=3228 CPUtime=0.16
/proc/9560/stat : 9560 (cudf_msu32) R 9559 9559 9023 34817 9081 4202496 630 0 0 0 16 0 0 0 25 0 1 0 892395272 3305472 522 1283457024 134512640 136125367 4293742944 18446744073709551615 134673201 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9560/statm: 807 522 157 394 0 411 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 5804

[startup+0.213898 s]
/proc/loadavg: 1.07 0.98 0.85 3/39 9560
/proc/meminfo: memFree=52180/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 892395272 2637824 279 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 279 238 194 0 30 0
[pid=9560] ppid=9559 vsize=3360 CPUtime=0.2
/proc/9560/stat : 9560 (cudf_msu32) R 9559 9559 9023 34817 9081 4202496 680 0 0 0 20 0 0 0 25 0 1 0 892395272 3440640 572 1283457024 134512640 136125367 4293742944 18446744073709551615 134516192 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9560/statm: 840 572 157 394 0 444 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 5936

[startup+0.303919 s]
/proc/loadavg: 1.07 0.98 0.85 3/39 9560
/proc/meminfo: memFree=52180/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 2576

[startup+0.703987 s]
/proc/loadavg: 1.07 0.98 0.85 3/39 9560
/proc/meminfo: memFree=52180/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 2576

[startup+1.50417 s]
/proc/loadavg: 1.07 0.98 0.85 2/40 9562
/proc/meminfo: memFree=47652/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=7196 CPUtime=1.22
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 1587 0 0 0 120 2 0 0 25 0 1 0 892395301 7368704 1354 1283457024 134512640 135887319 4293611856 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 1799 1354 137 336 0 1461 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 9772

[startup+3.10448 s]
/proc/loadavg: 1.07 0.98 0.85 2/40 9562
/proc/meminfo: memFree=45544/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=8676 CPUtime=2.81
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 1966 0 0 0 279 2 0 0 25 0 1 0 892395301 8884224 1720 1283457024 134512640 135887319 4293611856 18446744073709551615 134615348 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 2169 1720 137 336 0 1831 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 11252

[startup+6.30529 s]
/proc/loadavg: 1.06 0.98 0.85 2/40 9562
/proc/meminfo: memFree=44428/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=10128 CPUtime=6.01
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 2318 0 0 0 597 4 0 0 25 0 1 0 892395301 10371072 2072 1283457024 134512640 135887319 4293611856 18446744073709551615 134603397 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 2532 2072 137 336 0 2194 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 12704

[startup+12.7066 s]
/proc/loadavg: 1.06 0.98 0.85 2/40 9562
/proc/meminfo: memFree=42816/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=11052 CPUtime=12.4
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 2576 0 0 0 1234 6 0 0 25 0 1 0 892395301 11317248 2318 1283457024 134512640 135887319 4293611856 18446744073709551615 134615314 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 2763 2318 137 336 0 2425 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 13628

[startup+25.5092 s]
/proc/loadavg: 1.04 0.98 0.85 2/40 9562
/proc/meminfo: memFree=41328/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=12568 CPUtime=25.18
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 2977 0 0 0 2509 9 0 0 25 0 1 0 892395301 12869632 2687 1283457024 134512640 135887319 4293611856 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 3142 2687 137 336 0 2804 0
Current children cumulated CPU time (s) 25.44
Current children cumulated vsize (KiB) 15144

[startup+51.1058 s]
/proc/loadavg: 1.03 0.98 0.86 2/40 9562
/proc/meminfo: memFree=39468/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=14680 CPUtime=50.75
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 3548 0 0 0 5048 27 0 0 25 0 1 0 892395301 15032320 3226 1283457024 134512640 135887319 4293611856 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 3670 3226 137 336 0 3332 0
Current children cumulated CPU time (s) 51.01
Current children cumulated vsize (KiB) 17256

[startup+102.307 s]
/proc/loadavg: 1.01 0.98 0.86 2/40 9562
/proc/meminfo: memFree=36988/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=16716 CPUtime=101.87
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 4119 0 0 0 10133 54 0 0 25 0 1 0 892395301 17117184 3715 1283457024 134512640 135887319 4293611856 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 4179 3715 137 336 0 3841 0
Current children cumulated CPU time (s) 102.13
Current children cumulated vsize (KiB) 19292

[startup+162.311 s]
/proc/loadavg: 1.00 0.98 0.87 2/40 9562
/proc/meminfo: memFree=35004/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=18712 CPUtime=161.8
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 4660 0 0 0 16102 78 0 0 25 0 1 0 892395301 19161088 4194 1283457024 134512640 135887319 4293611856 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 4678 4194 137 336 0 4340 0
Current children cumulated CPU time (s) 162.06
Current children cumulated vsize (KiB) 21288

[startup+222.307 s]
/proc/loadavg: 1.00 0.98 0.87 2/40 9562
/proc/meminfo: memFree=33392/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=20172 CPUtime=221.72
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 5055 0 0 0 22078 94 0 0 25 0 1 0 892395301 20656128 4572 1283457024 134512640 135887319 4293611856 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 5043 4572 137 336 0 4705 0
Current children cumulated CPU time (s) 221.98
Current children cumulated vsize (KiB) 22748

[startup+282.307 s]
/proc/loadavg: 1.00 0.98 0.88 2/40 9562
/proc/meminfo: memFree=31408/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=22036 CPUtime=281.44
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 5583 0 0 0 28030 114 0 0 25 0 1 0 892395301 22564864 5051 1283457024 134512640 135887319 4293611856 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 5509 5051 137 336 0 5171 0
Current children cumulated CPU time (s) 281.7
Current children cumulated vsize (KiB) 24612



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.712 s]
/proc/loadavg: 1.00 0.98 0.88 2/40 9562
/proc/meminfo: memFree=31284/1048576 swapFree=2095372/2097144
[pid=9559] ppid=9558 vsize=2576 CPUtime=0.26
/proc/9559/stat : 9559 (cudf2pbo4parano) S 9558 9559 9023 34817 9081 4202496 402 772 0 0 0 0 25 1 23 0 1 0 892395272 2637824 282 1283457024 134512640 135304128 4292044640 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9559/statm: 644 282 241 194 0 30 0
[pid=9562] ppid=9559 vsize=22180 CPUtime=289.74
/proc/9562/stat : 9562 (bmo-pblex32) R 9559 9559 9023 34817 9081 4202496 5623 0 0 0 28857 117 0 0 25 0 1 0 892395301 22712320 5074 1283457024 134512640 135887319 4293611856 18446744073709551615 134614989 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9562/statm: 5545 5074 137 336 0 5207 0
Current children cumulated CPU time (s) 290
Current children cumulated vsize (KiB) 24756

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.743
CPU time (s): 290.038
CPU user time (s): 288.842
CPU system time (s): 1.19607
CPU usage (%): 99.7577
Max. virtual memory (cumulated for all children) (KiB): 24756

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 288.842
system time used= 1.19607
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 8297
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= 11
involuntary context switches= 3759

runsolver used 0.012 second user time and 0 second system time

The end