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/rand06f749.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand06f749.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand06f749.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.82 0.45 5/39 9262
/proc/meminfo: memFree=33172/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=0
/proc/9261/stat : 9261 (cudf2pbo4trendy) R 9260 9261 9023 34817 9081 4202496 365 0 0 0 0 0 0 0 25 0 1 0 892230250 2629632 278 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/9261/statm: 642 278 238 194 0 28 0
[pid=9262] ppid=9261 vsize=2568 CPUtime=0
/proc/9262/stat : 9262 (cudf2pbo4trendy) R 9261 9261 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 892230250 2629632 40 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/9262/statm: 642 40 0 194 0 28 0

[startup+0.185616 s]
/proc/loadavg: 0.85 0.82 0.45 5/39 9262
/proc/meminfo: memFree=33172/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=0
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892230250 2629632 278 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 278 238 194 0 28 0
[pid=9262] ppid=9261 vsize=9704 CPUtime=0.18
/proc/9262/stat : 9262 (cudf_msu32) R 9261 9261 9023 34817 9081 4202496 2249 0 0 0 16 2 0 0 25 0 1 0 892230250 9936896 2142 1283457024 134512640 136125367 4292677728 18446744073709551615 134718210 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9262/statm: 2426 2142 142 394 0 2030 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12272

[startup+0.205634 s]
/proc/loadavg: 0.85 0.82 0.45 5/39 9262
/proc/meminfo: memFree=33172/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=0
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892230250 2629632 278 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 278 238 194 0 28 0
[pid=9262] ppid=9261 vsize=10572 CPUtime=0.2
/proc/9262/stat : 9262 (cudf_msu32) R 9261 9261 9023 34817 9081 4202496 2444 0 0 0 18 2 0 0 25 0 1 0 892230250 10825728 2337 1283457024 134512640 136125367 4292677728 18446744073709551615 134728351 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9262/statm: 2643 2337 143 394 0 2247 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13140

[startup+0.305645 s]
/proc/loadavg: 0.85 0.82 0.45 5/39 9262
/proc/meminfo: memFree=33172/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=0
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892230250 2629632 278 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 278 238 194 0 28 0
[pid=9262] ppid=9261 vsize=14136 CPUtime=0.3
/proc/9262/stat : 9262 (cudf_msu32) R 9261 9261 9023 34817 9081 4202496 3329 0 0 0 27 3 0 0 25 0 1 0 892230250 14475264 3222 1283457024 134512640 136125367 4292677728 18446744073709551615 134717966 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9262/statm: 3534 3222 143 394 0 3138 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16704

[startup+0.705712 s]
/proc/loadavg: 0.85 0.82 0.45 5/39 9262
/proc/meminfo: memFree=33172/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=0
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 892230250 2629632 278 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 278 238 194 0 28 0
[pid=9262] ppid=9261 vsize=26476 CPUtime=0.7
/proc/9262/stat : 9262 (cudf_msu32) R 9261 9261 9023 34817 9081 4202496 6418 0 0 0 66 4 0 0 25 0 1 0 892230250 27111424 6311 1283457024 134512640 136125367 4292677728 18446744073709551615 134717925 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9262/statm: 6619 6311 143 394 0 6223 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 29044

[startup+1.50595 s]
/proc/loadavg: 0.95 0.84 0.46 2/40 9263
/proc/meminfo: memFree=6072/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 1.16
Current children cumulated vsize (KiB) 2568

[startup+3.10638 s]
/proc/loadavg: 0.95 0.84 0.46 2/40 9264
/proc/meminfo: memFree=27400/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=16068 CPUtime=1.93
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 4870 0 0 0 127 66 0 0 25 0 1 0 892230367 16453632 3699 1283457024 134512640 135887319 4292290560 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 4017 3699 144 336 0 3679 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 18636

[startup+6.30726 s]
/proc/loadavg: 0.95 0.84 0.46 2/40 9264
/proc/meminfo: memFree=16240/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=23548 CPUtime=5.11
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8106 0 0 0 408 103 0 0 25 0 1 0 892230367 24113152 5570 1283457024 134512640 135887319 4292290560 18446744073709551615 134604731 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 5887 5570 144 336 0 5549 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 26116

[startup+12.7065 s]
/proc/loadavg: 0.95 0.84 0.46 2/40 9264
/proc/meminfo: memFree=16240/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=23548 CPUtime=11.47
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8132 0 0 0 1042 105 0 0 25 0 1 0 892230367 24113152 5594 1283457024 134512640 135887319 4292290560 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 5887 5594 144 336 0 5549 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 26116

[startup+25.509 s]
/proc/loadavg: 0.96 0.85 0.47 2/40 9264
/proc/meminfo: memFree=16240/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=23724 CPUtime=24.28
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8180 0 0 0 2320 108 0 0 25 0 1 0 892230367 24293376 5629 1283457024 134512640 135887319 4292290560 18446744073709551615 134617784 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 5931 5629 144 336 0 5593 0
Current children cumulated CPU time (s) 25.44
Current children cumulated vsize (KiB) 26292

[startup+51.1132 s]
/proc/loadavg: 0.97 0.86 0.48 2/40 9264
/proc/meminfo: memFree=15248/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=24664 CPUtime=49.87
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8458 0 0 0 4879 108 0 0 25 0 1 0 892230367 25255936 5859 1283457024 134512640 135887319 4292290560 18446744073709551615 134615449 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 6166 5859 144 336 0 5828 0
Current children cumulated CPU time (s) 51.03
Current children cumulated vsize (KiB) 27232

Solver just ended. Dumping a history of the last processes samples

[startup+51.2132 s]
/proc/loadavg: 0.97 0.86 0.48 2/40 9264
/proc/meminfo: memFree=15248/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=24664 CPUtime=49.97
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8458 0 0 0 4889 108 0 0 25 0 1 0 892230367 25255936 5859 1283457024 134512640 135887319 4292290560 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 6166 5859 144 336 0 5828 0
Current children cumulated CPU time (s) 51.13
Current children cumulated vsize (KiB) 27232

[startup+54.4136 s]
/proc/loadavg: 0.97 0.86 0.48 2/40 9264
/proc/meminfo: memFree=15248/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=24664 CPUtime=53.17
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8478 0 0 0 5209 108 0 0 25 0 1 0 892230367 25255936 5879 1283457024 134512640 135887319 4292290560 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 6166 5879 144 336 0 5828 0
Current children cumulated CPU time (s) 54.33
Current children cumulated vsize (KiB) 27232

[startup+56.0138 s]
/proc/loadavg: 0.97 0.86 0.48 2/40 9264
/proc/meminfo: memFree=15124/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=24664 CPUtime=54.77
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8492 0 0 0 5369 108 0 0 25 0 1 0 892230367 25255936 5893 1283457024 134512640 135887319 4292290560 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 6166 5893 144 336 0 5828 0
Current children cumulated CPU time (s) 55.93
Current children cumulated vsize (KiB) 27232

[startup+56.8138 s]
/proc/loadavg: 0.98 0.86 0.48 2/40 9264
/proc/meminfo: memFree=15124/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=24796 CPUtime=55.57
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8496 0 0 0 5449 108 0 0 25 0 1 0 892230367 25391104 5897 1283457024 134512640 135887319 4292290560 18446744073709551615 134615085 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 6199 5897 144 336 0 5861 0
Current children cumulated CPU time (s) 56.73
Current children cumulated vsize (KiB) 27364

[startup+57.2139 s]
/proc/loadavg: 0.98 0.86 0.48 2/40 9264
/proc/meminfo: memFree=15124/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=1.16
/proc/9261/stat : 9261 (cudf2pbo4trendy) S 9260 9261 9023 34817 9081 4202496 402 8291 0 0 0 0 97 19 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
[pid=9264] ppid=9261 vsize=24796 CPUtime=55.97
/proc/9264/stat : 9264 (bmo-pblex32) R 9261 9261 9023 34817 9081 4202496 8500 0 0 0 5489 108 0 0 25 0 1 0 892230367 25391104 5901 1283457024 134512640 135887319 4292290560 18446744073709551615 134605901 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9264/statm: 6199 5901 144 336 0 5861 0
Current children cumulated CPU time (s) 57.13
Current children cumulated vsize (KiB) 27364

[startup+57.414 s]
/proc/loadavg: 0.98 0.86 0.48 2/40 9264
/proc/meminfo: memFree=15124/1048576 swapFree=2095372/2097144
[pid=9261] ppid=9260 vsize=2568 CPUtime=57.33
/proc/9261/stat : 9261 (cudf2pbo4trendy) R 9260 9261 9023 34817 9081 4202496 421 16797 0 0 0 0 5605 128 18 0 1 0 892230250 2629632 281 1283457024 134512640 135304128 4293794048 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/9261/statm: 642 281 241 194 0 28 0
Current children cumulated CPU time (s) 57.33
Current children cumulated vsize (KiB) 2568

Child status: 0
Real time (s): 57.4517
CPU time (s): 57.3876
CPU user time (s): 56.0795
CPU system time (s): 1.30808
CPU usage (%): 99.8884
Max. virtual memory (cumulated for all children) (KiB): 36432

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

runsolver used 0 second user time and 0 second system time

The end