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/rand847939.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//rand847939.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand847939.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 4/35 13202
/proc/meminfo: memFree=67520/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=0
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894475838 2633728 278 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 278 238 194 0 29 0
[pid=13202] ppid=13201 vsize=2052 CPUtime=0.01
/proc/13202/stat : 13202 (cudf_msu32) R 13201 13201 9023 34817 9081 4202496 311 0 0 0 1 0 0 0 25 0 1 0 894475838 2101248 203 1283457024 134512640 136125367 4287847360 18446744073709551615 135535081 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13202/statm: 513 203 141 394 0 117 0

[startup+0.125413 s]
/proc/loadavg: 0.96 0.95 0.91 4/35 13202
/proc/meminfo: memFree=67520/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=0
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894475838 2633728 278 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 278 238 194 0 29 0
[pid=13202] ppid=13201 vsize=7332 CPUtime=0.13
/proc/13202/stat : 13202 (cudf_msu32) R 13201 13201 9023 34817 9081 4202496 1653 0 0 0 13 0 0 0 25 0 1 0 894475838 7507968 1545 1283457024 134512640 136125367 4287847360 18446744073709551615 134718168 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13202/statm: 1833 1545 142 394 0 1437 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 9904

[startup+0.205442 s]
/proc/loadavg: 0.96 0.95 0.91 4/35 13202
/proc/meminfo: memFree=67520/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=0
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894475838 2633728 278 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 278 238 194 0 29 0
[pid=13202] ppid=13201 vsize=10576 CPUtime=0.2
/proc/13202/stat : 13202 (cudf_msu32) R 13201 13201 9023 34817 9081 4202496 2445 0 0 0 19 1 0 0 25 0 1 0 894475838 10829824 2337 1283457024 134512640 136125367 4287847360 18446744073709551615 134728315 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13202/statm: 2644 2337 143 394 0 2248 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13148

[startup+0.305448 s]
/proc/loadavg: 0.96 0.95 0.91 4/35 13202
/proc/meminfo: memFree=67520/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=0
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894475838 2633728 278 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 278 238 194 0 29 0
[pid=13202] ppid=13201 vsize=14140 CPUtime=0.3
/proc/13202/stat : 13202 (cudf_msu32) R 13201 13201 9023 34817 9081 4202496 3349 0 0 0 29 1 0 0 25 0 1 0 894475838 14479360 3241 1283457024 134512640 136125367 4287847360 18446744073709551615 134727078 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13202/statm: 3535 3241 143 394 0 3139 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16712

[startup+0.705529 s]
/proc/loadavg: 0.96 0.95 0.91 4/35 13202
/proc/meminfo: memFree=67520/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=0
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894475838 2633728 278 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 278 238 194 0 29 0
[pid=13202] ppid=13201 vsize=26480 CPUtime=0.71
/proc/13202/stat : 13202 (cudf_msu32) R 13201 13201 9023 34817 9081 4202496 6428 0 0 0 65 6 0 0 25 0 1 0 894475838 27115520 6320 1283457024 134512640 136125367 4287847360 18446744073709551615 134710438 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13202/statm: 6620 6320 143 394 0 6224 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 29052

[startup+1.50571 s]
/proc/loadavg: 0.96 0.95 0.91 2/36 13203
/proc/meminfo: memFree=33028/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 1.25
Current children cumulated vsize (KiB) 2572

[startup+3.10617 s]
/proc/loadavg: 0.96 0.95 0.91 2/36 13204
/proc/meminfo: memFree=53736/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=17604 CPUtime=1.84
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 5474 0 0 0 126 58 0 0 25 0 1 0 894475963 18026496 4066 1283457024 134512640 135887319 4291327776 18446744073709551615 134709519 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 4401 4066 144 336 0 4063 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 20176

[startup+6.30702 s]
/proc/loadavg: 0.96 0.95 0.91 2/36 13204
/proc/meminfo: memFree=40104/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=27536 CPUtime=5.03
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 9549 0 0 0 358 145 0 0 25 0 1 0 894475963 28196864 6642 1283457024 134512640 135887319 4291327776 18446744073709551615 134600832 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 6884 6642 144 336 0 6546 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 30108

[startup+12.7086 s]
/proc/loadavg: 0.97 0.95 0.91 2/36 13204
/proc/meminfo: memFree=38492/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=29292 CPUtime=11.43
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 9987 0 0 0 973 170 0 0 25 0 1 0 894475963 29995008 7062 1283457024 134512640 135887319 4291327776 18446744073709551615 134605883 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 7323 7062 144 336 0 6985 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 31864

[startup+25.5114 s]
/proc/loadavg: 0.97 0.95 0.91 2/36 13204
/proc/meminfo: memFree=36632/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=31008 CPUtime=24.22
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 10428 0 0 0 2250 172 0 0 25 0 1 0 894475963 31752192 7500 1283457024 134512640 135887319 4291327776 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 7752 7500 144 336 0 7414 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 33580

[startup+51.1072 s]
/proc/loadavg: 0.98 0.95 0.91 2/36 13204
/proc/meminfo: memFree=33780/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=33912 CPUtime=49.81
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 11173 0 0 0 4807 174 0 0 25 0 1 0 894475963 34725888 8233 1283457024 134512640 135887319 4291327776 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 8478 8233 144 336 0 8140 0
Current children cumulated CPU time (s) 51.06
Current children cumulated vsize (KiB) 36484

[startup+102.311 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 13204
/proc/meminfo: memFree=27208/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=40412 CPUtime=100.93
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 12875 0 0 0 9905 188 0 0 25 0 1 0 894475963 41381888 9846 1283457024 134512640 135887319 4291327776 18446744073709551615 134617710 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 10103 9846 144 336 0 9765 0
Current children cumulated CPU time (s) 102.18
Current children cumulated vsize (KiB) 42984

[startup+162.313 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 13204
/proc/meminfo: memFree=22868/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=44588 CPUtime=160.88
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 13973 0 0 0 15895 193 0 0 25 0 1 0 894475963 45658112 10907 1283457024 134512640 135887319 4291327776 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 11147 10907 144 336 0 10809 0
Current children cumulated CPU time (s) 162.13
Current children cumulated vsize (KiB) 47160

[startup+222.306 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 13204
/proc/meminfo: memFree=22868/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=44588 CPUtime=220.8
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 13973 0 0 0 21875 205 0 0 25 0 1 0 894475963 45658112 10907 1283457024 134512640 135887319 4291327776 18446744073709551615 134606243 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 11147 10907 144 336 0 10809 0
Current children cumulated CPU time (s) 222.05
Current children cumulated vsize (KiB) 47160

[startup+282.31 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 13204
/proc/meminfo: memFree=22744/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=44588 CPUtime=280.75
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 13974 0 0 0 27861 214 0 0 25 0 1 0 894475963 45658112 10908 1283457024 134512640 135887319 4291327776 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 11147 10908 144 336 0 10809 0
Current children cumulated CPU time (s) 282
Current children cumulated vsize (KiB) 47160



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.312 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 13204
/proc/meminfo: memFree=22744/1048576 swapFree=2095372/2097144
[pid=13201] ppid=13200 vsize=2572 CPUtime=1.25
/proc/13201/stat : 13201 (cudf2pbo4trendy) S 13200 13201 9023 34817 9081 4202496 402 8814 0 0 0 0 103 22 20 0 1 0 894475838 2633728 281 1283457024 134512640 135304128 4287656736 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13201/statm: 643 281 241 194 0 29 0
[pid=13204] ppid=13201 vsize=44588 CPUtime=288.75
/proc/13204/stat : 13204 (bmo-pblex32) R 13201 13201 9023 34817 9081 4202496 13974 0 0 0 28661 214 0 0 25 0 1 0 894475963 45658112 10908 1283457024 134512640 135887319 4291327776 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13204/statm: 11147 10908 144 336 0 10809 0
Current children cumulated CPU time (s) 290
Current children cumulated vsize (KiB) 47160

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.378
CPU time (s): 290.07
CPU user time (s): 287.694
CPU system time (s): 2.37615
CPU usage (%): 99.8941
Max. virtual memory (cumulated for all children) (KiB): 47160

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

runsolver used 0 second user time and 0 second system time

The end