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/cudf2pbo4paranoid-1.0/rand655e63.cudf.impossible.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/impossible//rand655e63.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand655e63.cudf.impossible.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.94 0.90 5/39 10523
/proc/meminfo: memFree=35616/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=0
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893036829 2633728 278 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 278 238 194 0 29 0
[pid=10523] ppid=10522 vsize=1916 CPUtime=0
/proc/10523/stat : 10523 (cudf_msu32) D 10522 10522 9023 34817 9081 4202496 263 0 0 0 0 0 0 0 25 0 1 0 893036829 1961984 156 1283457024 134512640 136125367 4286614160 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/10523/statm: 479 156 133 394 0 83 0

[startup+0.134975 s]
/proc/loadavg: 0.85 0.94 0.90 5/39 10523
/proc/meminfo: memFree=35616/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=0
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893036829 2633728 278 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 278 238 194 0 29 0
[pid=10523] ppid=10522 vsize=6732 CPUtime=0.1
/proc/10523/stat : 10523 (cudf_msu32) R 10522 10522 9023 34817 9081 4202496 1506 0 0 0 10 0 0 0 25 0 1 0 893036829 6893568 1399 1283457024 134512640 136125367 4286614160 18446744073709551615 135543688 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10523/statm: 1683 1399 143 394 0 1287 0
Current children cumulated CPU time (s) 0.1
Current children cumulated vsize (KiB) 9304

[startup+0.206965 s]
/proc/loadavg: 0.85 0.94 0.90 5/39 10523
/proc/meminfo: memFree=35616/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=0
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893036829 2633728 278 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 278 238 194 0 29 0
[pid=10523] ppid=10522 vsize=9372 CPUtime=0.17
/proc/10523/stat : 10523 (cudf_msu32) R 10522 10522 9023 34817 9081 4202496 2162 0 0 0 17 0 0 0 25 0 1 0 893036829 9596928 2055 1283457024 134512640 136125367 4286614160 18446744073709551615 134717628 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10523/statm: 2343 2055 143 394 0 1947 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 11944

[startup+0.306972 s]
/proc/loadavg: 0.85 0.94 0.90 5/39 10523
/proc/meminfo: memFree=35616/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=0
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893036829 2633728 278 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 278 238 194 0 29 0
[pid=10523] ppid=10522 vsize=12960 CPUtime=0.26
/proc/10523/stat : 10523 (cudf_msu32) R 10522 10522 9023 34817 9081 4202496 3050 0 0 0 26 0 0 0 25 0 1 0 893036829 13271040 2943 1283457024 134512640 136125367 4286614160 18446744073709551615 134727103 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10523/statm: 3240 2943 144 394 0 2844 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 15532

[startup+0.707017 s]
/proc/loadavg: 0.85 0.94 0.90 5/39 10523
/proc/meminfo: memFree=35616/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=0
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893036829 2633728 278 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 278 238 194 0 29 0
[pid=10523] ppid=10522 vsize=24904 CPUtime=0.58
/proc/10523/stat : 10523 (cudf_msu32) R 10522 10522 9023 34817 9081 4202496 6033 0 0 0 56 2 0 0 25 0 1 0 893036829 25501696 5926 1283457024 134512640 136125367 4286614160 18446744073709551615 135533302 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10523/statm: 6226 5926 144 394 0 5830 0
Current children cumulated CPU time (s) 0.58
Current children cumulated vsize (KiB) 27476

[startup+1.50707 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 10524
/proc/meminfo: memFree=5964/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=0
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 25 0 1 0 893036829 2633728 278 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 278 238 194 0 29 0
[pid=10523] ppid=10522 vsize=45292 CPUtime=1.32
/proc/10523/stat : 10523 (cudf_msu32) R 10522 10522 9023 34817 9081 4202496 11180 0 0 0 126 6 0 0 25 0 1 0 893036829 46379008 11024 1283457024 134512640 136125367 4286614160 18446744073709551615 135594526 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10523/statm: 11323 11024 144 394 0 10927 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 47864

[startup+3.10813 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 10524
/proc/meminfo: memFree=6088/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=2.14
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 402 14725 0 0 0 0 181 33 18 0 1 0 893036829 2633728 281 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 2.14
Current children cumulated vsize (KiB) 2572
heavy processes:

[startup+6.30918 s]
/proc/loadavg: 0.87 0.94 0.90 2/40 10525
/proc/meminfo: memFree=39692/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=2.14
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 402 14725 0 0 0 0 181 33 18 0 1 0 893036829 2633728 281 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 281 241 194 0 29 0
[pid=10525] ppid=10522 vsize=25964 CPUtime=3.96
/proc/10525/stat : 10525 (bmo-pblex32) R 10522 10522 9023 34817 9081 4202496 7685 0 0 0 296 100 0 0 25 0 1 0 893037062 26587136 6194 1283457024 134512640 135887319 4288144400 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10525/statm: 6491 6194 144 336 0 6153 0
Current children cumulated CPU time (s) 6.1
Current children cumulated vsize (KiB) 28536

[startup+12.7109 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10525
/proc/meminfo: memFree=35228/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=2.14
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 402 14725 0 0 0 0 181 33 18 0 1 0 893036829 2633728 281 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 281 241 194 0 29 0
[pid=10525] ppid=10522 vsize=30376 CPUtime=10.29
/proc/10525/stat : 10525 (bmo-pblex32) R 10522 10522 9023 34817 9081 4202496 8796 0 0 0 833 196 0 0 25 0 1 0 893037062 31105024 7297 1283457024 134512640 135887319 4288144400 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10525/statm: 7594 7297 144 336 0 7256 0
Current children cumulated CPU time (s) 12.43
Current children cumulated vsize (KiB) 32948

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

[startup+12.811 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10525
/proc/meminfo: memFree=35228/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=2.14
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 402 14725 0 0 0 0 181 33 18 0 1 0 893036829 2633728 281 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 281 241 194 0 29 0
[pid=10525] ppid=10522 vsize=30376 CPUtime=10.39
/proc/10525/stat : 10525 (bmo-pblex32) R 10522 10522 9023 34817 9081 4202496 8813 0 0 0 842 197 0 0 25 0 1 0 893037062 31105024 7314 1283457024 134512640 135887319 4288144400 18446744073709551615 134615592 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10525/statm: 7594 7314 144 336 0 7256 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 32948

[startup+13.6112 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10525
/proc/meminfo: memFree=34608/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=2.14
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 402 14725 0 0 0 0 181 33 18 0 1 0 893036829 2633728 281 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 281 241 194 0 29 0
[pid=10525] ppid=10522 vsize=30912 CPUtime=11.19
/proc/10525/stat : 10525 (bmo-pblex32) R 10522 10522 9023 34817 9081 4202496 8970 0 0 0 917 202 0 0 25 0 1 0 893037062 31653888 7457 1283457024 134512640 135887319 4288144400 18446744073709551615 134598364 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10525/statm: 7728 7457 144 336 0 7390 0
Current children cumulated CPU time (s) 13.33
Current children cumulated vsize (KiB) 33484

[startup+13.8112 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10525
/proc/meminfo: memFree=34608/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=2.14
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 402 14725 0 0 0 0 181 33 18 0 1 0 893036829 2633728 281 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 281 241 194 0 29 0
[pid=10525] ppid=10522 vsize=31044 CPUtime=11.39
/proc/10525/stat : 10525 (bmo-pblex32) R 10522 10522 9023 34817 9081 4202496 8984 0 0 0 936 203 0 0 25 0 1 0 893037062 31789056 7468 1283457024 134512640 135887319 4288144400 18446744073709551615 134614978 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10525/statm: 7761 7468 144 336 0 7423 0
Current children cumulated CPU time (s) 13.53
Current children cumulated vsize (KiB) 33616

[startup+13.9112 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10525
/proc/meminfo: memFree=34608/1048576 swapFree=2095372/2097144
[pid=10522] ppid=10521 vsize=2572 CPUtime=13.59
/proc/10522/stat : 10522 (cudf2pbo4parano) S 10521 10522 9023 34817 9081 4202496 432 23713 0 0 0 0 1123 236 18 0 1 0 893036829 2633728 281 1283457024 134512640 135304128 4294750688 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10522/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 13.59
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 13.9439
CPU time (s): 13.6689
CPU user time (s): 11.2927
CPU system time (s): 2.37615
CPU usage (%): 98.0272
Max. virtual memory (cumulated for all children) (KiB): 62000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.2927
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= 26062
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= 66
involuntary context switches= 5398

runsolver used 0 second user time and 0.012 second system time

The end