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/rand3dec28.cudf.impossible.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/impossible//rand3dec28.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand3dec28.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 10122
/proc/meminfo: memFree=61844/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=0
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892789892 2633728 278 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 278 238 194 0 29 0
[pid=10122] ppid=10121 vsize=1916 CPUtime=0
/proc/10122/stat : 10122 (cudf_msu32) D 10121 10121 9023 34817 9081 4202496 264 0 0 0 0 0 0 0 25 0 1 0 892789892 1961984 157 1283457024 134512640 136125367 4288672896 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/10122/statm: 479 157 133 394 0 83 0

[startup+0.113069 s]
/proc/loadavg: 0.85 0.94 0.90 5/39 10122
/proc/meminfo: memFree=61844/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=0
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892789892 2633728 278 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 278 238 194 0 29 0
[pid=10122] ppid=10121 vsize=6068 CPUtime=0.07
/proc/10122/stat : 10122 (cudf_msu32) D 10121 10121 9023 34817 9081 4202496 1339 0 0 0 7 0 0 0 25 0 1 0 892789892 6213632 1232 1283457024 134512640 136125367 4288672896 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/10122/statm: 1517 1232 143 394 0 1121 0
Current children cumulated CPU time (s) 0.07
Current children cumulated vsize (KiB) 8640

[startup+0.202968 s]
/proc/loadavg: 0.85 0.94 0.90 5/39 10122
/proc/meminfo: memFree=61844/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=0
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892789892 2633728 278 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 278 238 194 0 29 0
[pid=10122] ppid=10121 vsize=9368 CPUtime=0.16
/proc/10122/stat : 10122 (cudf_msu32) R 10121 10121 9023 34817 9081 4202496 2164 0 0 0 16 0 0 0 25 0 1 0 892789892 9592832 2057 1283457024 134512640 136125367 4288672896 18446744073709551615 134717792 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10122/statm: 2342 2057 143 394 0 1946 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11940

[startup+0.306982 s]
/proc/loadavg: 0.85 0.94 0.90 5/39 10122
/proc/meminfo: memFree=61844/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=0
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892789892 2633728 278 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 278 238 194 0 29 0
[pid=10122] ppid=10121 vsize=13088 CPUtime=0.26
/proc/10122/stat : 10122 (cudf_msu32) R 10121 10121 9023 34817 9081 4202496 3085 0 0 0 26 0 0 0 25 0 1 0 892789892 13402112 2978 1283457024 134512640 136125367 4288672896 18446744073709551615 134727251 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10122/statm: 3272 2978 144 394 0 2876 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 15660

[startup+0.706999 s]
/proc/loadavg: 0.85 0.94 0.90 5/39 10122
/proc/meminfo: memFree=61844/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=0
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892789892 2633728 278 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 278 238 194 0 29 0
[pid=10122] ppid=10121 vsize=25164 CPUtime=0.61
/proc/10122/stat : 10122 (cudf_msu32) R 10121 10121 9023 34817 9081 4202496 6094 0 0 0 59 2 0 0 25 0 1 0 892789892 25767936 5987 1283457024 134512640 136125367 4288672896 18446744073709551615 134717966 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10122/statm: 6291 5987 144 394 0 5895 0
Current children cumulated CPU time (s) 0.61
Current children cumulated vsize (KiB) 27736

[startup+1.50707 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 10123
/proc/meminfo: memFree=8292/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=0
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 892789892 2633728 278 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 278 238 194 0 29 0
[pid=10122] ppid=10121 vsize=45552 CPUtime=1.3
/proc/10122/stat : 10122 (cudf_msu32) R 10121 10121 9023 34817 9081 4202496 11236 0 0 0 126 4 0 0 25 0 1 0 892789892 46645248 11080 1283457024 134512640 136125367 4288672896 18446744073709551615 135301568 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10122/statm: 11388 11080 144 394 0 10992 0
Current children cumulated CPU time (s) 1.3
Current children cumulated vsize (KiB) 48124

[startup+3.10483 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 10123
/proc/meminfo: memFree=6076/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=2.11
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 401 14739 0 0 0 0 180 31 18 0 1 0 892789892 2633728 281 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 2.11
Current children cumulated vsize (KiB) 2572
heavy processes:

[startup+6.3053 s]
/proc/loadavg: 0.87 0.94 0.90 2/40 10124
/proc/meminfo: memFree=39308/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=2.11
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 401 14739 0 0 0 0 180 31 18 0 1 0 892789892 2633728 281 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 281 241 194 0 29 0
[pid=10124] ppid=10121 vsize=26204 CPUtime=3.85
/proc/10124/stat : 10124 (bmo-pblex32) R 10121 10121 9023 34817 9081 4202496 7773 0 0 0 304 81 0 0 25 0 1 0 892790124 26832896 6284 1283457024 134512640 135887319 4286952176 18446744073709551615 134598359 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10124/statm: 6551 6284 144 336 0 6213 0
Current children cumulated CPU time (s) 5.96
Current children cumulated vsize (KiB) 28776

[startup+12.7084 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10124
/proc/meminfo: memFree=34844/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=2.11
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 401 14739 0 0 0 0 180 31 18 0 1 0 892789892 2633728 281 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 281 241 194 0 29 0
[pid=10124] ppid=10121 vsize=30724 CPUtime=10.19
/proc/10124/stat : 10124 (bmo-pblex32) R 10121 10121 9023 34817 9081 4202496 8918 0 0 0 829 190 0 0 25 0 1 0 892790124 31461376 7415 1283457024 134512640 135887319 4286952176 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10124/statm: 7681 7415 144 336 0 7343 0
Current children cumulated CPU time (s) 12.3
Current children cumulated vsize (KiB) 33296

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

[startup+12.8085 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10124
/proc/meminfo: memFree=34844/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=2.11
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 401 14739 0 0 0 0 180 31 18 0 1 0 892789892 2633728 281 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 281 241 194 0 29 0
[pid=10124] ppid=10121 vsize=30856 CPUtime=10.29
/proc/10124/stat : 10124 (bmo-pblex32) R 10121 10121 9023 34817 9081 4202496 8937 0 0 0 838 191 0 0 25 0 1 0 892790124 31596544 7434 1283457024 134512640 135887319 4286952176 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10124/statm: 7714 7434 144 336 0 7376 0
Current children cumulated CPU time (s) 12.4
Current children cumulated vsize (KiB) 33428

[startup+13.6089 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10124
/proc/meminfo: memFree=34100/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=2.11
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 401 14739 0 0 0 0 180 31 18 0 1 0 892789892 2633728 281 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 281 241 194 0 29 0
[pid=10124] ppid=10121 vsize=31524 CPUtime=11.1
/proc/10124/stat : 10124 (bmo-pblex32) R 10121 10121 9023 34817 9081 4202496 9108 0 0 0 910 200 0 0 25 0 1 0 892790124 32280576 7589 1283457024 134512640 135887319 4286952176 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10124/statm: 7881 7589 144 336 0 7543 0
Current children cumulated CPU time (s) 13.21
Current children cumulated vsize (KiB) 34096

[startup+13.809 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10124
/proc/meminfo: memFree=34100/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=2.11
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 401 14739 0 0 0 0 180 31 18 0 1 0 892789892 2633728 281 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 281 241 194 0 29 0
[pid=10124] ppid=10121 vsize=31524 CPUtime=11.3
/proc/10124/stat : 10124 (bmo-pblex32) R 10121 10121 9023 34817 9081 4202496 9136 0 0 0 930 200 0 0 25 0 1 0 892790124 32280576 7613 1283457024 134512640 135887319 4286952176 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10124/statm: 7881 7613 144 336 0 7543 0
Current children cumulated CPU time (s) 13.41
Current children cumulated vsize (KiB) 34096

[startup+13.909 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 10124
/proc/meminfo: memFree=34100/1048576 swapFree=2095372/2097144
[pid=10121] ppid=10120 vsize=2572 CPUtime=13.46
/proc/10121/stat : 10121 (cudf2pbo4parano) S 10120 10121 9023 34817 9081 4202496 432 23887 0 0 0 0 1114 232 18 0 1 0 892789892 2633728 281 1283457024 134512640 135304128 4289141904 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10121/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 13.46
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 13.933
CPU time (s): 13.5448
CPU user time (s): 11.2087
CPU system time (s): 2.33615
CPU usage (%): 97.2144
Max. virtual memory (cumulated for all children) (KiB): 62000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.2087
system time used= 2.33615
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 26236
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= 76
involuntary context switches= 5818

runsolver used 0 second user time and 0.012 second system time

The end