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/rand2fe899.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand2fe899.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand2fe899.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.96 0.95 0.91 5/39 10865
/proc/meminfo: memFree=63816/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=0
/proc/10864/stat : 10864 (cudf2pbo4trendy) R 10863 10864 9023 34817 9081 4202496 365 0 0 0 0 0 0 0 25 0 1 0 893282445 2633728 278 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/10864/statm: 643 278 238 194 0 29 0
[pid=10865] ppid=10864 vsize=2572 CPUtime=0
/proc/10865/stat : 10865 (cudf2pbo4trendy) R 10864 10864 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 893282445 2633728 40 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/10865/statm: 643 40 0 194 0 29 0

[startup+0.135571 s]
/proc/loadavg: 0.96 0.95 0.91 5/39 10865
/proc/meminfo: memFree=63816/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=0
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893282445 2633728 278 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 278 238 194 0 29 0
[pid=10865] ppid=10864 vsize=7728 CPUtime=0.13
/proc/10865/stat : 10865 (cudf_msu32) R 10864 10864 9023 34817 9081 4202496 1745 0 0 0 13 0 0 0 25 0 1 0 893282445 7913472 1638 1283457024 134512640 136125367 4287195936 18446744073709551615 135543683 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10865/statm: 1932 1638 142 394 0 1536 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 10300

[startup+0.205593 s]
/proc/loadavg: 0.96 0.95 0.91 5/39 10865
/proc/meminfo: memFree=63816/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=0
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893282445 2633728 278 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 278 238 194 0 29 0
[pid=10865] ppid=10864 vsize=10576 CPUtime=0.2
/proc/10865/stat : 10865 (cudf_msu32) R 10864 10864 9023 34817 9081 4202496 2444 0 0 0 20 0 0 0 25 0 1 0 893282445 10829824 2337 1283457024 134512640 136125367 4287195936 18446744073709551615 134728322 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10865/statm: 2644 2337 143 394 0 2248 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13148

[startup+0.3056 s]
/proc/loadavg: 0.96 0.95 0.91 5/39 10865
/proc/meminfo: memFree=63816/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=0
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893282445 2633728 278 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 278 238 194 0 29 0
[pid=10865] ppid=10864 vsize=14140 CPUtime=0.3
/proc/10865/stat : 10865 (cudf_msu32) R 10864 10864 9023 34817 9081 4202496 3341 0 0 0 29 1 0 0 25 0 1 0 893282445 14479360 3234 1283457024 134512640 136125367 4287195936 18446744073709551615 134717285 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10865/statm: 3535 3234 143 394 0 3139 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16712

[startup+0.705669 s]
/proc/loadavg: 0.96 0.95 0.91 5/39 10865
/proc/meminfo: memFree=63816/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=0
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893282445 2633728 278 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 278 238 194 0 29 0
[pid=10865] ppid=10864 vsize=26480 CPUtime=0.7
/proc/10865/stat : 10865 (cudf_msu32) R 10864 10864 9023 34817 9081 4202496 6428 0 0 0 67 3 0 0 25 0 1 0 893282445 27115520 6321 1283457024 134512640 136125367 4287195936 18446744073709551615 134718131 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10865/statm: 6620 6321 143 394 0 6224 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 29052

[startup+1.50583 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10866
/proc/meminfo: memFree=29820/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 1.2
Current children cumulated vsize (KiB) 2572

[startup+3.11046 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10867
/proc/meminfo: memFree=51644/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=16352 CPUtime=1.8
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 5038 0 0 0 117 63 0 0 25 0 1 0 893282566 16744448 3797 1283457024 134512640 135887319 4294855280 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 4088 3797 144 336 0 3750 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 18924

[startup+6.31137 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10867
/proc/meminfo: memFree=39616/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=24564 CPUtime=4.96
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 8539 0 0 0 396 100 0 0 25 0 1 0 893282566 25153536 5891 1283457024 134512640 135887319 4294855280 18446744073709551615 134603647 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 6141 5891 144 336 0 5803 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 27136

[startup+12.7026 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10867
/proc/meminfo: memFree=38748/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=25356 CPUtime=11.36
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 8743 0 0 0 1034 102 0 0 25 0 1 0 893282566 25964544 6088 1283457024 134512640 135887319 4294855280 18446744073709551615 134603644 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 6339 6088 144 336 0 6001 0
Current children cumulated CPU time (s) 12.56
Current children cumulated vsize (KiB) 27928

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

[startup+12.8127 s]
/proc/loadavg: 0.96 0.95 0.91 2/40 10867
/proc/meminfo: memFree=38748/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=25356 CPUtime=11.47
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 8745 0 0 0 1045 102 0 0 25 0 1 0 893282566 25964544 6090 1283457024 134512640 135887319 4294855280 18446744073709551615 134603644 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 6339 6090 144 336 0 6001 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 27928

[startup+14.4129 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10867
/proc/meminfo: memFree=38624/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=25488 CPUtime=13.07
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 8777 0 0 0 1205 102 0 0 25 0 1 0 893282566 26099712 6122 1283457024 134512640 135887319 4294855280 18446744073709551615 134603579 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 6372 6122 144 336 0 6034 0
Current children cumulated CPU time (s) 14.27
Current children cumulated vsize (KiB) 28060

[startup+16.0131 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10867
/proc/meminfo: memFree=38500/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=25620 CPUtime=14.67
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 8809 0 0 0 1365 102 0 0 25 0 1 0 893282566 26234880 6153 1283457024 134512640 135887319 4294855280 18446744073709551615 134603587 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 6405 6153 144 336 0 6067 0
Current children cumulated CPU time (s) 15.87
Current children cumulated vsize (KiB) 28192

[startup+16.4131 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10867
/proc/meminfo: memFree=38500/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=25752 CPUtime=15.07
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 8816 0 0 0 1405 102 0 0 25 0 1 0 893282566 26370048 6160 1283457024 134512640 135887319 4294855280 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 6438 6160 144 336 0 6100 0
Current children cumulated CPU time (s) 16.27
Current children cumulated vsize (KiB) 28324

[startup+16.8132 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10867
/proc/meminfo: memFree=38500/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=25752 CPUtime=15.47
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 8825 0 0 0 1445 102 0 0 25 0 1 0 893282566 26370048 6169 1283457024 134512640 135887319 4294855280 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 6438 6169 144 336 0 6100 0
Current children cumulated CPU time (s) 16.67
Current children cumulated vsize (KiB) 28324

[startup+16.9032 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10867
/proc/meminfo: memFree=38500/1048576 swapFree=2095372/2097144
[pid=10864] ppid=10863 vsize=2572 CPUtime=1.2
/proc/10864/stat : 10864 (cudf2pbo4trendy) S 10863 10864 9023 34817 9081 4202496 402 8680 0 0 0 0 102 18 18 0 1 0 893282445 2633728 281 1283457024 134512640 135304128 4294361488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10864/statm: 643 281 241 194 0 29 0
[pid=10867] ppid=10864 vsize=25752 CPUtime=15.56
/proc/10867/stat : 10867 (bmo-pblex32) R 10864 10864 9023 34817 9081 4202496 8826 0 0 0 1454 102 0 0 25 0 1 0 893282566 26370048 6170 1283457024 134512640 135887319 4294855280 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10867/statm: 6438 6170 144 336 0 6100 0
Current children cumulated CPU time (s) 16.76
Current children cumulated vsize (KiB) 28324

Child status: 0
Real time (s): 16.9969
CPU time (s): 16.8571
CPU user time (s): 15.649
CPU system time (s): 1.20807
CPU usage (%): 99.1774
Max. virtual memory (cumulated for all children) (KiB): 37556

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

runsolver used 0 second user time and 0 second system time

The end