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/huge1.cudf.cudf_set.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/cudf_set//huge1.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/huge1.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: 0.02 0.01 0.00 1/38 9093
/proc/meminfo: memFree=5460/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=3024 CPUtime=0
/proc/9093/stat : 9093 (runsolver) D 9092 9093 9023 34817 9081 4202560 73 0 0 0 0 0 0 0 25 0 1 0 892169432 3096576 94 1283457024 134512640 134586868 4290000032 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/9093/statm: 756 94 62 19 0 54 0

[startup+0.138813 s]
/proc/loadavg: 0.02 0.01 0.00 1/38 9093
/proc/meminfo: memFree=5460/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 892169432 2633728 279 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 279 238 194 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.214909 s]
/proc/loadavg: 0.02 0.01 0.00 1/38 9093
/proc/meminfo: memFree=5460/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 892169432 2633728 279 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 279 238 194 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.314926 s]
/proc/loadavg: 0.02 0.01 0.00 1/38 9093
/proc/meminfo: memFree=5460/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 892169432 2633728 279 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 279 238 194 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.712095 s]
/proc/loadavg: 0.02 0.01 0.00 1/38 9093
/proc/meminfo: memFree=5460/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 0.25
Current children cumulated vsize (KiB) 2572

[startup+1.51223 s]
/proc/loadavg: 0.02 0.01 0.00 2/40 9096
/proc/meminfo: memFree=5916/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=6920 CPUtime=1.04
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 1503 0 15 0 104 0 0 0 25 0 1 0 892169471 7086080 1285 1283457024 134512640 135887319 4287566048 18446744073709551615 134615057 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 1730 1285 137 336 0 1392 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 9492

[startup+3.11261 s]
/proc/loadavg: 0.02 0.01 0.00 2/40 9096
/proc/meminfo: memFree=6264/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=8768 CPUtime=2.64
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 1961 0 15 0 263 1 0 0 25 0 1 0 892169471 8978432 1730 1283457024 134512640 135887319 4287566048 18446744073709551615 134615032 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 2192 1730 137 336 0 1854 0
Current children cumulated CPU time (s) 2.89
Current children cumulated vsize (KiB) 11340

[startup+6.30351 s]
/proc/loadavg: 0.10 0.02 0.01 2/40 9096
/proc/meminfo: memFree=6160/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=10088 CPUtime=5.82
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 2297 0 15 0 580 2 0 0 25 0 1 0 892169471 10330112 2066 1283457024 134512640 135887319 4287566048 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 2522 2066 137 336 0 2184 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 12660

[startup+12.7053 s]
/proc/loadavg: 0.17 0.04 0.01 2/40 9100
/proc/meminfo: memFree=6216/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=11372 CPUtime=12.02
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 2641 0 15 0 1194 8 0 0 25 0 1 0 892169471 11644928 2376 1283457024 134512640 135887319 4287566048 18446744073709551615 134605371 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 2843 2376 137 336 0 2505 0
Current children cumulated CPU time (s) 12.27
Current children cumulated vsize (KiB) 13944

[startup+25.5105 s]
/proc/loadavg: 0.35 0.09 0.02 2/41 9127
/proc/meminfo: memFree=5660/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=12824 CPUtime=24.78
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 3029 0 15 0 2462 16 0 0 25 0 1 0 892169471 13131776 2748 1283457024 134512640 135887319 4287566048 18446744073709551615 134615339 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 3206 2748 137 336 0 2868 0
Current children cumulated CPU time (s) 25.03
Current children cumulated vsize (KiB) 15396

[startup+51.1075 s]
/proc/loadavg: 0.70 0.19 0.06 2/41 9136
/proc/meminfo: memFree=11396/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=14156 CPUtime=48.83
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 3421 0 15 0 4855 28 0 0 25 0 1 0 892169471 14495744 3095 1283457024 134512640 135887319 4287566048 18446744073709551615 134615116 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 3539 3095 137 336 0 3201 0
Current children cumulated CPU time (s) 49.08
Current children cumulated vsize (KiB) 16728

[startup+102.313 s]
/proc/loadavg: 0.91 0.33 0.11 2/39 9136
/proc/meminfo: memFree=13288/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=16932 CPUtime=99.99
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 4156 0 15 0 9958 41 0 0 25 0 1 0 892169471 17338368 3779 1283457024 134512640 135887319 4287566048 18446744073709551615 134615116 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 4233 3779 137 336 0 3895 0
Current children cumulated CPU time (s) 100.24
Current children cumulated vsize (KiB) 19504

[startup+162.307 s]
/proc/loadavg: 0.96 0.45 0.16 2/39 9136
/proc/meminfo: memFree=11552/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=18720 CPUtime=159.97
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 4657 0 15 0 15932 65 0 0 25 0 1 0 892169471 19169280 4204 1283457024 134512640 135887319 4287566048 18446744073709551615 134615130 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 4680 4204 137 336 0 4342 0
Current children cumulated CPU time (s) 160.22
Current children cumulated vsize (KiB) 21292

[startup+222.312 s]
/proc/loadavg: 0.98 0.55 0.21 2/39 9136
/proc/meminfo: memFree=10064/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=20196 CPUtime=219.97
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 5078 0 15 0 21915 82 0 0 25 0 1 0 892169471 20680704 4564 1283457024 134512640 135887319 4287566048 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 5049 4564 137 336 0 4711 0
Current children cumulated CPU time (s) 220.22
Current children cumulated vsize (KiB) 22768

[startup+282.308 s]
/proc/loadavg: 0.99 0.63 0.26 2/39 9136
/proc/meminfo: memFree=9072/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=21276 CPUtime=279.97
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 5372 0 15 0 27904 93 0 0 25 0 1 0 892169471 21786624 4823 1283457024 134512640 135887319 4287566048 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 5319 4823 137 336 0 4981 0
Current children cumulated CPU time (s) 280.22
Current children cumulated vsize (KiB) 23848



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+292.11 s]
/proc/loadavg: 0.99 0.64 0.27 2/39 9136
/proc/meminfo: memFree=8948/1048576 swapFree=2095372/2097144
[pid=9093] ppid=9092 vsize=2572 CPUtime=0.25
/proc/9093/stat : 9093 (cudf2pbo4parano) S 9092 9093 9023 34817 9081 4202496 404 755 0 17 0 0 23 2 22 0 1 0 892169432 2633728 282 1283457024 134512640 135304128 4290164112 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9093/statm: 643 282 241 194 0 29 0
[pid=9096] ppid=9093 vsize=21408 CPUtime=289.77
/proc/9096/stat : 9096 (bmo-pblex32) R 9093 9093 9023 34817 9081 4202496 5418 0 15 0 28877 100 0 0 25 0 1 0 892169471 21921792 4859 1283457024 134512640 135887319 4287566048 18446744073709551615 134614991 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9096/statm: 5352 4859 137 336 0 5014 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 23980

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): 292.149
CPU time (s): 290.05
CPU user time (s): 289.018
CPU system time (s): 1.03206
CPU usage (%): 99.2815
Max. virtual memory (cumulated for all children) (KiB): 23980

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.018
system time used= 1.03206
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 8078
page faults= 32
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 55
involuntary context switches= 5044

runsolver used 0 second user time and 0.004 second system time

The end