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/huge2.cudf.cudf_set.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/cudf_set//huge2.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-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: 0.85 0.95 0.87 5/39 9580
/proc/meminfo: memFree=51216/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 892425347 2633728 279 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 279 238 194 0 29 0
[pid=9580] ppid=9579 vsize=2184 CPUtime=0.02
/proc/9580/stat : 9580 (cudf_msu32) R 9579 9579 9023 34817 9081 4202496 345 0 0 0 2 0 0 0 25 0 1 0 892425347 2236416 237 1283457024 134512640 136125367 4288603264 18446744073709551615 134717966 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9580/statm: 546 237 139 394 0 150 0

[startup+0.165246 s]
/proc/loadavg: 0.85 0.95 0.87 5/39 9580
/proc/meminfo: memFree=51216/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 892425347 2633728 279 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 279 238 194 0 29 0
[pid=9580] ppid=9579 vsize=3232 CPUtime=0.17
/proc/9580/stat : 9580 (cudf_msu32) R 9579 9579 9023 34817 9081 4202496 622 0 0 0 17 0 0 0 25 0 1 0 892425347 3309568 514 1283457024 134512640 136125367 4288603264 18446744073709551615 134673174 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9580/statm: 808 514 157 394 0 412 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 5804

[startup+0.20527 s]
/proc/loadavg: 0.85 0.95 0.87 5/39 9580
/proc/meminfo: memFree=51216/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 18 0 1 0 892425347 2633728 279 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 279 238 194 0 29 0
[pid=9580] ppid=9579 vsize=3364 CPUtime=0.21
/proc/9580/stat : 9580 (cudf_msu32) R 9579 9579 9023 34817 9081 4202496 680 0 0 0 21 0 0 0 25 0 1 0 892425347 3444736 572 1283457024 134512640 136125367 4288603264 18446744073709551615 134516192 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9580/statm: 841 572 157 394 0 445 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 5936

[startup+0.305338 s]
/proc/loadavg: 0.85 0.95 0.87 5/39 9580
/proc/meminfo: memFree=51216/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 2572

[startup+0.705362 s]
/proc/loadavg: 0.85 0.95 0.87 5/39 9580
/proc/meminfo: memFree=51216/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 2572

[startup+1.50553 s]
/proc/loadavg: 0.85 0.95 0.87 2/40 9582
/proc/meminfo: memFree=47032/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=7336 CPUtime=1.21
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 1613 0 0 0 119 2 0 0 25 0 1 0 892425377 7512064 1385 1283457024 134512640 135887319 4289738144 18446744073709551615 134604970 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 1834 1385 137 336 0 1496 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 9908

[startup+3.10575 s]
/proc/loadavg: 0.85 0.95 0.87 2/40 9582
/proc/meminfo: memFree=45048/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=9056 CPUtime=2.81
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 2073 0 0 0 278 3 0 0 25 0 1 0 892425377 9273344 1829 1283457024 134512640 135887319 4289738144 18446744073709551615 134604731 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 2264 1829 137 336 0 1926 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 11628

[startup+6.30624 s]
/proc/loadavg: 0.86 0.95 0.87 2/40 9582
/proc/meminfo: memFree=43560/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=9848 CPUtime=6.01
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 2285 0 0 0 596 5 0 0 25 0 1 0 892425377 10084352 2039 1283457024 134512640 135887319 4289738144 18446744073709551615 134605150 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 2462 2039 137 336 0 2124 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 12420

[startup+12.7076 s]
/proc/loadavg: 0.87 0.95 0.87 2/40 9582
/proc/meminfo: memFree=42072/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=11300 CPUtime=12.39
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 2650 0 0 0 1226 13 0 0 25 0 1 0 892425377 11571200 2394 1283457024 134512640 135887319 4289738144 18446744073709551615 134615061 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 2825 2394 137 336 0 2487 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 13872

[startup+25.5101 s]
/proc/loadavg: 0.90 0.95 0.87 2/40 9582
/proc/meminfo: memFree=39840/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=13520 CPUtime=25.18
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 3290 0 0 0 2500 18 0 0 25 0 1 0 892425377 13844480 2942 1283457024 134512640 135887319 4289738144 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 3380 2942 137 336 0 3042 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 16092

[startup+51.1066 s]
/proc/loadavg: 0.93 0.96 0.87 2/40 9582
/proc/meminfo: memFree=38104/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=15104 CPUtime=50.74
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 3713 0 0 0 5051 23 0 0 25 0 1 0 892425377 15466496 3350 1283457024 134512640 135887319 4289738144 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 3776 3350 137 336 0 3438 0
Current children cumulated CPU time (s) 51.03
Current children cumulated vsize (KiB) 17676

[startup+102.31 s]
/proc/loadavg: 0.97 0.96 0.88 2/40 9582
/proc/meminfo: memFree=35252/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=17916 CPUtime=101.87
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 4457 0 0 0 10144 43 0 0 25 0 1 0 892425377 18345984 4020 1283457024 134512640 135887319 4289738144 18446744073709551615 134615042 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 4479 4020 137 336 0 4141 0
Current children cumulated CPU time (s) 102.16
Current children cumulated vsize (KiB) 20488

[startup+162.306 s]
/proc/loadavg: 0.99 0.97 0.89 2/40 9582
/proc/meminfo: memFree=33144/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=20032 CPUtime=161.79
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 5018 0 0 0 16108 71 0 0 25 0 1 0 892425377 20512768 4540 1283457024 134512640 135887319 4289738144 18446744073709551615 134615414 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 5008 4540 137 336 0 4670 0
Current children cumulated CPU time (s) 162.08
Current children cumulated vsize (KiB) 22604

[startup+222.31 s]
/proc/loadavg: 0.99 0.97 0.89 2/40 9582
/proc/meminfo: memFree=32400/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=20600 CPUtime=221.68
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 5221 0 0 0 22075 93 0 0 25 0 1 0 892425377 21094400 4691 1283457024 134512640 135887319 4289738144 18446744073709551615 134614989 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 5150 4691 137 336 0 4812 0
Current children cumulated CPU time (s) 221.97
Current children cumulated vsize (KiB) 23172

[startup+282.305 s]
/proc/loadavg: 0.99 0.97 0.90 2/40 9582
/proc/meminfo: memFree=30664/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=22328 CPUtime=281.59
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 5708 0 0 0 28047 112 0 0 25 0 1 0 892425377 22863872 5131 1283457024 134512640 135887319 4289738144 18446744073709551615 134615116 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 5582 5131 137 336 0 5244 0
Current children cumulated CPU time (s) 281.88
Current children cumulated vsize (KiB) 24900



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.507 s]
/proc/loadavg: 0.99 0.97 0.90 2/40 9582
/proc/meminfo: memFree=30540/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=22328 CPUtime=289.79
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 5710 0 0 0 28866 113 0 0 25 0 1 0 892425377 22863872 5133 1283457024 134512640 135887319 4289738144 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 5582 5133 137 336 0 5244 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 24900

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.507 s]
/proc/loadavg: 0.99 0.97 0.90 2/40 9582
/proc/meminfo: memFree=30540/1048576 swapFree=2095372/2097144
[pid=9579] ppid=9578 vsize=2572 CPUtime=0.29
/proc/9579/stat : 9579 (cudf2pbo4trendy) S 9578 9579 9023 34817 9081 4202496 403 831 0 0 0 0 29 0 23 0 1 0 892425347 2633728 282 1283457024 134512640 135304128 4287861600 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9579/statm: 643 282 241 194 0 29 0
[pid=9582] ppid=9579 vsize=22328 CPUtime=289.79
/proc/9582/stat : 9582 (bmo-pblex32) R 9579 9579 9023 34817 9081 4202496 5710 0 0 0 28866 113 0 0 25 0 1 0 892425377 22863872 5133 1283457024 134512640 135887319 4289738144 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9582/statm: 5582 5133 137 336 0 5244 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 24900

Child status: 0
Real time (s): 290.538
CPU time (s): 290.126
CPU user time (s): 288.974
CPU system time (s): 1.15207
CPU usage (%): 99.8581
Max. virtual memory (cumulated for all children) (KiB): 24900

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 288.974
system time used= 1.15207
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 8442
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= 3757

runsolver used 0 second user time and 0 second system time

The end