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/rand2d2fd0.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand2d2fd0.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand2d2fd0.cudf.difficult.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.85 0.94 0.90 4/39 10463
/proc/meminfo: memFree=33368/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=0
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 18 0 1 0 893006450 2629632 277 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 277 238 194 0 28 0
[pid=10463] ppid=10462 vsize=2044 CPUtime=0
/proc/10463/stat : 10463 (cudf_msu32) R 10462 10462 9023 34817 9081 4202496 309 0 0 0 0 0 0 0 25 0 1 0 893006450 2093056 202 1283457024 134512640 136125367 4290166256 18446744073709551615 134728348 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10463/statm: 511 202 141 394 0 115 0

[startup+0.185421 s]
/proc/loadavg: 0.85 0.94 0.90 4/39 10463
/proc/meminfo: memFree=33368/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=0
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 18 0 1 0 893006450 2629632 277 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 277 238 194 0 28 0
[pid=10463] ppid=10462 vsize=9568 CPUtime=0.18
/proc/10463/stat : 10463 (cudf_msu32) R 10462 10462 9023 34817 9081 4202496 2216 0 0 0 16 2 0 0 25 0 1 0 893006450 9797632 2109 1283457024 134512640 136125367 4290166256 18446744073709551615 135549901 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10463/statm: 2392 2109 142 394 0 1996 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12136

[startup+0.205421 s]
/proc/loadavg: 0.85 0.94 0.90 4/39 10463
/proc/meminfo: memFree=33368/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=0
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 18 0 1 0 893006450 2629632 277 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 277 238 194 0 28 0
[pid=10463] ppid=10462 vsize=10240 CPUtime=0.2
/proc/10463/stat : 10463 (cudf_msu32) R 10462 10462 9023 34817 9081 4202496 2384 0 0 0 18 2 0 0 25 0 1 0 893006450 10485760 2277 1283457024 134512640 136125367 4290166256 18446744073709551615 134717605 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10463/statm: 2560 2277 142 394 0 2164 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12808

[startup+0.305437 s]
/proc/loadavg: 0.85 0.94 0.90 4/39 10463
/proc/meminfo: memFree=33368/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=0
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 18 0 1 0 893006450 2629632 277 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 277 238 194 0 28 0
[pid=10463] ppid=10462 vsize=14000 CPUtime=0.3
/proc/10463/stat : 10463 (cudf_msu32) R 10462 10462 9023 34817 9081 4202496 3309 0 0 0 28 2 0 0 25 0 1 0 893006450 14336000 3202 1283457024 134512640 136125367 4290166256 18446744073709551615 134717885 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10463/statm: 3500 3202 143 394 0 3104 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16568

[startup+0.705517 s]
/proc/loadavg: 0.85 0.94 0.90 4/39 10463
/proc/meminfo: memFree=33368/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=0
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 18 0 1 0 893006450 2629632 277 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 277 238 194 0 28 0
[pid=10463] ppid=10462 vsize=26340 CPUtime=0.7
/proc/10463/stat : 10463 (cudf_msu32) R 10462 10462 9023 34817 9081 4202496 6404 0 0 0 65 5 0 0 25 0 1 0 893006450 26972160 6297 1283457024 134512640 136125367 4290166256 18446744073709551615 135543652 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10463/statm: 6585 6297 143 394 0 6189 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 28908

[startup+1.50566 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 10464
/proc/meminfo: memFree=5164/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
Current children cumulated CPU time (s) 1.17
Current children cumulated vsize (KiB) 2568

[startup+3.106 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 10465
/proc/meminfo: memFree=27384/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=16176 CPUtime=1.92
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 5014 0 0 0 124 68 0 0 25 0 1 0 893006568 16564224 3732 1283457024 134512640 135887319 4293511472 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 4044 3732 144 336 0 3706 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 18744

[startup+6.30684 s]
/proc/loadavg: 0.87 0.94 0.90 2/40 10465
/proc/meminfo: memFree=15852/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=24612 CPUtime=5.09
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 8533 0 0 0 350 159 0 0 25 0 1 0 893006568 25202688 5904 1283457024 134512640 135887319 4293511472 18446744073709551615 134598437 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 6153 5904 144 336 0 5815 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 27180

[startup+12.7083 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10465
/proc/meminfo: memFree=14364/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=25404 CPUtime=11.49
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 8734 0 0 0 983 166 0 0 25 0 1 0 893006568 26013696 6101 1283457024 134512640 135887319 4293511472 18446744073709551615 134605912 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 6351 6101 144 336 0 6013 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 27972

[startup+25.5109 s]
/proc/loadavg: 0.90 0.94 0.90 2/40 10465
/proc/meminfo: memFree=13248/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=26732 CPUtime=24.3
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 9058 0 0 0 2258 172 0 0 25 0 1 0 893006568 27373568 6409 1283457024 134512640 135887319 4293511472 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 6683 6409 144 336 0 6345 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 29300

[startup+51.1069 s]
/proc/loadavg: 0.93 0.94 0.90 2/40 10465
/proc/meminfo: memFree=10644/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=29264 CPUtime=49.83
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 9740 0 0 0 4805 178 0 0 25 0 1 0 893006568 29966336 7054 1283457024 134512640 135887319 4293511472 18446744073709551615 134617912 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 7316 7054 144 336 0 6978 0
Current children cumulated CPU time (s) 51
Current children cumulated vsize (KiB) 31832

[startup+102.308 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10465
/proc/meminfo: memFree=5312/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=34480 CPUtime=100.99
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 11152 0 0 0 9911 188 0 0 25 0 1 0 893006568 35307520 8342 1283457024 134512640 135887319 4293511472 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 8620 8342 144 336 0 8282 0
Current children cumulated CPU time (s) 102.16
Current children cumulated vsize (KiB) 37048

[startup+162.311 s]
/proc/loadavg: 0.99 0.95 0.91 2/40 10465
/proc/meminfo: memFree=5508/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=37844 CPUtime=160.92
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 12080 0 0 0 15896 196 0 0 25 0 1 0 893006568 38752256 9151 1283457024 134512640 135887319 4293511472 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 9461 9151 144 336 0 9123 0
Current children cumulated CPU time (s) 162.09
Current children cumulated vsize (KiB) 40412

[startup+222.305 s]
/proc/loadavg: 0.99 0.96 0.91 2/40 10465
/proc/meminfo: memFree=5384/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=37844 CPUtime=220.86
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 12082 0 0 0 21882 204 0 0 25 0 1 0 893006568 38752256 9153 1283457024 134512640 135887319 4293511472 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 9461 9153 144 336 0 9123 0
Current children cumulated CPU time (s) 222.03
Current children cumulated vsize (KiB) 40412

[startup+282.307 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10465
/proc/meminfo: memFree=6136/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=40392 CPUtime=280.83
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 12789 0 0 0 27865 218 0 0 25 0 1 0 893006568 41361408 9828 1283457024 134512640 135887319 4293511472 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 10098 9828 144 336 0 9760 0
Current children cumulated CPU time (s) 282
Current children cumulated vsize (KiB) 42960



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.409 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10465
/proc/meminfo: memFree=6136/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=40392 CPUtime=288.91
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 12790 0 0 0 28671 220 0 0 25 0 1 0 893006568 41361408 9829 1283457024 134512640 135887319 4293511472 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 10098 9829 144 336 0 9760 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 42960

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.409 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10465
/proc/meminfo: memFree=6136/1048576 swapFree=2095372/2097144
[pid=10462] ppid=10461 vsize=2568 CPUtime=1.17
/proc/10462/stat : 10462 (cudf2pbo4trendy) S 10461 10462 9023 34817 9081 4202496 399 8316 0 0 0 0 100 17 20 0 1 0 893006450 2629632 280 1283457024 134512640 135304128 4291337904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10462/statm: 642 280 241 194 0 28 0
[pid=10465] ppid=10462 vsize=40392 CPUtime=288.91
/proc/10465/stat : 10465 (bmo-pblex32) R 10462 10462 9023 34817 9081 4202496 12790 0 0 0 28671 220 0 0 25 0 1 0 893006568 41361408 9829 1283457024 134512640 135887319 4293511472 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10465/statm: 10098 9829 144 336 0 9760 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 42960

Child status: 0
Real time (s): 290.469
CPU time (s): 290.162
CPU user time (s): 287.754
CPU system time (s): 2.40815
CPU usage (%): 99.8944
Max. virtual memory (cumulated for all children) (KiB): 42960

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

runsolver used 0 second user time and 0 second system time

The end