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/randf17677.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//randf17677.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/randf17677.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.87 0.93 0.90 2/34 14382
/proc/meminfo: memFree=32764/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2560 CPUtime=0
/proc/14382/stat : 14382 (cudf2pbo4trendy) R 14381 14382 9023 34817 9081 4202496 315 0 0 0 0 0 0 0 25 0 1 0 894799647 2621440 229 1283457024 134512640 135304128 4292433840 18446744073709551615 135014385 0 0 4 65536 0 0 0 17 0 0 0 0
/proc/14382/statm: 640 229 191 194 0 26 0

[startup+0.177363 s]
/proc/loadavg: 0.87 0.93 0.90 2/34 14382
/proc/meminfo: memFree=32764/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=0
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 894799647 2633728 279 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 279 238 194 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.207388 s]
/proc/loadavg: 0.87 0.93 0.90 2/34 14382
/proc/meminfo: memFree=32764/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=0
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 894799647 2633728 279 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 279 238 194 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.307405 s]
/proc/loadavg: 0.87 0.93 0.90 2/34 14382
/proc/meminfo: memFree=32764/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=0
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 894799647 2633728 279 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 279 238 194 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+0.707537 s]
/proc/loadavg: 0.87 0.93 0.90 2/34 14382
/proc/meminfo: memFree=32764/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=0
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 894799647 2633728 279 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 279 238 194 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2572

[startup+1.5078 s]
/proc/loadavg: 0.87 0.93 0.90 2/36 14384
/proc/meminfo: memFree=5152/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 1.16
Current children cumulated vsize (KiB) 2572

[startup+3.10837 s]
/proc/loadavg: 0.87 0.93 0.90 2/36 14385
/proc/meminfo: memFree=27372/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=16472 CPUtime=1.91
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 5081 0 0 0 123 68 0 0 25 0 1 0 894799765 16867328 3808 1283457024 134512640 135887319 4294632000 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 4118 3808 144 336 0 3780 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 19044

[startup+6.30909 s]
/proc/loadavg: 0.88 0.93 0.90 2/36 14385
/proc/meminfo: memFree=15344/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=25328 CPUtime=5.09
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 8704 0 0 0 370 139 0 0 25 0 1 0 894799765 25935872 6057 1283457024 134512640 135887319 4294632000 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 6332 6057 144 336 0 5994 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 27900

[startup+12.7112 s]
/proc/loadavg: 0.89 0.93 0.90 2/36 14385
/proc/meminfo: memFree=13988/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=26120 CPUtime=11.42
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 8907 0 0 0 999 143 0 0 25 0 1 0 894799765 26746880 6248 1283457024 134512640 135887319 4294632000 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 6530 6248 144 336 0 6192 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 28692

[startup+25.5039 s]
/proc/loadavg: 0.91 0.94 0.90 2/38 14387
/proc/meminfo: memFree=11096/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=28036 CPUtime=24.16
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9430 0 0 0 2262 154 0 0 25 0 1 0 894799765 28708864 6726 1283457024 134512640 135887319 4294632000 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7009 6726 144 336 0 6671 0
Current children cumulated CPU time (s) 25.32
Current children cumulated vsize (KiB) 30608

[startup+51.1088 s]
/proc/loadavg: 0.94 0.94 0.90 2/37 14388
/proc/meminfo: memFree=10508/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=29176 CPUtime=49.74
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9738 0 0 0 4811 163 0 0 25 0 1 0 894799765 29876224 6997 1283457024 134512640 135887319 4294632000 18446744073709551615 134615120 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7294 6997 144 336 0 6956 0
Current children cumulated CPU time (s) 50.9
Current children cumulated vsize (KiB) 31748

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

[startup+51.2089 s]
/proc/loadavg: 0.94 0.94 0.90 2/37 14388
/proc/meminfo: memFree=10508/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=29176 CPUtime=49.84
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9738 0 0 0 4821 163 0 0 25 0 1 0 894799765 29876224 6997 1283457024 134512640 135887319 4294632000 18446744073709551615 134615483 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7294 6997 144 336 0 6956 0
Current children cumulated CPU time (s) 51
Current children cumulated vsize (KiB) 31748

[startup+54.4093 s]
/proc/loadavg: 0.94 0.94 0.91 2/37 14388
/proc/meminfo: memFree=10508/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=29492 CPUtime=53.04
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9858 0 0 0 5141 163 0 0 25 0 1 0 894799765 30199808 7066 1283457024 134512640 135887319 4294632000 18446744073709551615 134605843 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7373 7066 144 336 0 7035 0
Current children cumulated CPU time (s) 54.2
Current children cumulated vsize (KiB) 32064

[startup+57.6101 s]
/proc/loadavg: 0.94 0.94 0.91 2/37 14388
/proc/meminfo: memFree=10260/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=29756 CPUtime=56.25
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9954 0 0 0 5461 164 0 0 25 0 1 0 894799765 30470144 7147 1283457024 134512640 135887319 4294632000 18446744073709551615 134615085 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7439 7147 144 336 0 7101 0
Current children cumulated CPU time (s) 57.41
Current children cumulated vsize (KiB) 32328

[startup+58.4103 s]
/proc/loadavg: 0.95 0.94 0.91 2/37 14388
/proc/meminfo: memFree=10136/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=29888 CPUtime=57.05
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9975 0 0 0 5541 164 0 0 25 0 1 0 894799765 30605312 7166 1283457024 134512640 135887319 4294632000 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7472 7166 144 336 0 7134 0
Current children cumulated CPU time (s) 58.21
Current children cumulated vsize (KiB) 32460

[startup+58.8104 s]
/proc/loadavg: 0.95 0.94 0.91 2/37 14388
/proc/meminfo: memFree=10136/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=29888 CPUtime=57.45
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9985 0 0 0 5581 164 0 0 25 0 1 0 894799765 30605312 7176 1283457024 134512640 135887319 4294632000 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7472 7176 144 336 0 7134 0
Current children cumulated CPU time (s) 58.61
Current children cumulated vsize (KiB) 32460

[startup+59.2105 s]
/proc/loadavg: 0.95 0.94 0.91 2/37 14388
/proc/meminfo: memFree=10136/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=29888 CPUtime=57.85
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9992 0 0 0 5621 164 0 0 25 0 1 0 894799765 30605312 7183 1283457024 134512640 135887319 4294632000 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7472 7183 144 336 0 7134 0
Current children cumulated CPU time (s) 59.01
Current children cumulated vsize (KiB) 32460

[startup+59.3105 s]
/proc/loadavg: 0.95 0.94 0.91 2/37 14388
/proc/meminfo: memFree=10136/1048576 swapFree=2095372/2097144
[pid=14382] ppid=14381 vsize=2572 CPUtime=1.16
/proc/14382/stat : 14382 (cudf2pbo4trendy) S 14381 14382 9023 34817 9081 4202496 402 8337 0 0 0 0 94 22 18 0 1 0 894799647 2633728 282 1283457024 134512640 135304128 4292433840 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/14382/statm: 643 282 241 194 0 29 0
[pid=14385] ppid=14382 vsize=29888 CPUtime=57.95
/proc/14385/stat : 14385 (bmo-pblex32) R 14382 14382 9023 34817 9081 4202496 9999 0 0 0 5631 164 0 0 25 0 1 0 894799765 30605312 7187 1283457024 134512640 135887319 4294632000 18446744073709551615 134617982 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/14385/statm: 7472 7187 144 336 0 7134 0
Current children cumulated CPU time (s) 59.11
Current children cumulated vsize (KiB) 32460

Child status: 0
Real time (s): 59.369
CPU time (s): 59.1877
CPU user time (s): 57.2956
CPU system time (s): 1.89212
CPU usage (%): 99.6946
Max. virtual memory (cumulated for all children) (KiB): 36516

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

runsolver used 0 second user time and 0 second system time

The end