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/201012091704/cudf2pbo4user-1.0/rand81406f.cudf.impossible.log.runsolver ./cudf2pbo4user-1.0 /home/misc2010/data/2010/impossible//rand81406f.cudf /home/misc2010/tmp/201012091704/cudf2pbo4user-1.0/rand81406f.cudf.impossible.result -changed,-notuptodate,-removed,-new 

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: 1.11 1.07 1.02 5/39 6009
/proc/meminfo: memFree=419612/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=0
/proc/6008/stat : 6008 (cudf2pbo4user-1) R 6007 6008 25521 34816 2180 4202496 368 0 0 0 0 0 0 0 25 0 1 0 901329841 2633728 281 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/6008/statm: 643 281 240 194 0 29 0
[pid=6009] ppid=6008 vsize=2572 CPUtime=0
/proc/6009/stat : 6009 (cudf2pbo4user-1) R 6008 6008 25521 34816 2180 4202560 0 0 0 0 0 0 0 0 25 0 1 0 901329841 2633728 41 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/6009/statm: 643 41 0 194 0 29 0

[startup+0.122958 s]
/proc/loadavg: 1.11 1.07 1.02 5/39 6009
/proc/meminfo: memFree=419612/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=0
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 386 0 0 0 0 0 0 0 25 0 1 0 901329841 2633728 281 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 281 240 194 0 29 0
[pid=6009] ppid=6008 vsize=6464 CPUtime=0.09
/proc/6009/stat : 6009 (cudf_msu32) R 6008 6008 25521 34816 2180 4202496 1413 0 0 0 7 2 0 0 25 0 1 0 901329841 6619136 1305 1283457024 134512640 136125367 4288928928 18446744073709551615 134727103 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6009/statm: 1616 1305 146 394 0 1220 0
Current children cumulated CPU time (s) 0.09
Current children cumulated vsize (KiB) 9036

[startup+0.21297 s]
/proc/loadavg: 1.11 1.07 1.02 5/39 6009
/proc/meminfo: memFree=419612/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=0
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 386 0 0 0 0 0 0 0 25 0 1 0 901329841 2633728 281 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 281 240 194 0 29 0
[pid=6009] ppid=6008 vsize=9764 CPUtime=0.18
/proc/6009/stat : 6009 (cudf_msu32) R 6008 6008 25521 34816 2180 4202496 2252 0 0 0 14 4 0 0 25 0 1 0 901329841 9998336 2144 1283457024 134512640 136125367 4288928928 18446744073709551615 135543670 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6009/statm: 2441 2144 146 394 0 2045 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12336

[startup+0.302985 s]
/proc/loadavg: 1.11 1.07 1.02 5/39 6009
/proc/meminfo: memFree=419612/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=0
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 386 0 0 0 0 0 0 0 25 0 1 0 901329841 2633728 281 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 281 240 194 0 29 0
[pid=6009] ppid=6008 vsize=12956 CPUtime=0.27
/proc/6009/stat : 6009 (cudf_msu32) R 6008 6008 25521 34816 2180 4202496 3065 0 0 0 21 6 0 0 25 0 1 0 901329841 13266944 2957 1283457024 134512640 136125367 4288928928 18446744073709551615 134717794 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6009/statm: 3239 2957 147 394 0 2843 0
Current children cumulated CPU time (s) 0.27
Current children cumulated vsize (KiB) 15528

[startup+0.703032 s]
/proc/loadavg: 1.11 1.07 1.02 5/39 6009
/proc/meminfo: memFree=419612/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=0
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 386 0 0 0 0 0 0 0 25 0 1 0 901329841 2633728 281 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 281 240 194 0 29 0
[pid=6009] ppid=6008 vsize=25296 CPUtime=0.68
/proc/6009/stat : 6009 (cudf_msu32) R 6008 6008 25521 34816 2180 4202496 6129 0 0 0 60 8 0 0 25 0 1 0 901329841 25903104 6021 1283457024 134512640 136125367 4288928928 18446744073709551615 135528873 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6009/statm: 6324 6021 147 394 0 5928 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 27868

[startup+1.50313 s]
/proc/loadavg: 1.11 1.07 1.02 2/40 6010
/proc/meminfo: memFree=385368/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=0
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 386 0 0 0 0 0 0 0 25 0 1 0 901329841 2633728 281 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 281 240 194 0 29 0
[pid=6009] ppid=6008 vsize=46092 CPUtime=1.47
/proc/6009/stat : 6009 (cudf_msu32) R 6008 6008 25521 34816 2180 4202496 11395 0 0 0 135 12 0 0 25 0 1 0 901329841 47198208 11238 1283457024 134512640 136125367 4288928928 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/6009/statm: 11523 11238 157 394 0 11127 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 48664

[startup+3.10545 s]
/proc/loadavg: 1.11 1.07 1.02 2/40 6010
/proc/meminfo: memFree=356476/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=2.43
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 404 15777 0 0 0 0 198 45 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 2.43
Current children cumulated vsize (KiB) 2572
heavy processes:

[startup+6.30627 s]
/proc/loadavg: 1.10 1.07 1.02 2/40 6011
/proc/meminfo: memFree=394296/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=2.43
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 404 15777 0 0 0 0 198 45 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
[pid=6011] ppid=6008 vsize=23904 CPUtime=3.79
/proc/6011/stat : 6011 (bmo-pblex32) R 6008 6008 25521 34816 2180 4202496 6341 0 0 0 301 78 0 0 25 0 1 0 901330087 24477696 5620 1283457024 134512640 135887319 4289887680 18446744073709551615 135049712 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6011/statm: 5976 5620 138 336 0 5638 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 26476

[startup+12.7076 s]
/proc/loadavg: 1.09 1.07 1.02 2/40 6011
/proc/meminfo: memFree=384128/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=2.43
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 404 15777 0 0 0 0 198 45 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
[pid=6011] ppid=6008 vsize=33600 CPUtime=10.18
/proc/6011/stat : 6011 (bmo-pblex32) R 6008 6008 25521 34816 2180 4202496 9772 0 0 0 884 134 0 0 25 0 1 0 901330087 34406400 8078 1283457024 134512640 135887319 4289887680 18446744073709551615 134605881 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6011/statm: 8400 8078 144 336 0 8062 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 36172

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

[startup+12.8076 s]
/proc/loadavg: 1.09 1.07 1.02 2/40 6011
/proc/meminfo: memFree=384128/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=2.43
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 404 15777 0 0 0 0 198 45 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
[pid=6011] ppid=6008 vsize=33600 CPUtime=10.28
/proc/6011/stat : 6011 (bmo-pblex32) R 6008 6008 25521 34816 2180 4202496 9772 0 0 0 894 134 0 0 25 0 1 0 901330087 34406400 8078 1283457024 134512640 135887319 4289887680 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6011/statm: 8400 8078 144 336 0 8062 0
Current children cumulated CPU time (s) 12.71
Current children cumulated vsize (KiB) 36172

[startup+16.0082 s]
/proc/loadavg: 1.08 1.07 1.02 2/40 6011
/proc/meminfo: memFree=375944/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=2.43
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 404 15777 0 0 0 0 198 45 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
[pid=6011] ppid=6008 vsize=41844 CPUtime=13.49
/proc/6011/stat : 6011 (bmo-pblex32) R 6008 6008 25521 34816 2180 4202496 12911 0 0 0 1213 136 0 0 25 0 1 0 901330087 42848256 10121 1283457024 134512640 135887319 4289887680 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6011/statm: 10461 10121 144 336 0 10123 0
Current children cumulated CPU time (s) 15.92
Current children cumulated vsize (KiB) 44416

[startup+19.2089 s]
/proc/loadavg: 1.08 1.07 1.02 2/40 6011
/proc/meminfo: memFree=375572/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=2.43
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 404 15777 0 0 0 0 198 45 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
[pid=6011] ppid=6008 vsize=49640 CPUtime=16.67
/proc/6011/stat : 6011 (bmo-pblex32) R 6008 6008 25521 34816 2180 4202496 15840 0 0 0 1520 147 0 0 25 0 1 0 901330087 50831360 12077 1283457024 134512640 135887319 4289887680 18446744073709551615 135318682 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6011/statm: 12410 12077 144 336 0 12072 0
Current children cumulated CPU time (s) 19.1
Current children cumulated vsize (KiB) 52212

[startup+20.0092 s]
/proc/loadavg: 1.08 1.07 1.02 2/40 6011
/proc/meminfo: memFree=367636/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=2.43
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 404 15777 0 0 0 0 198 45 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
[pid=6011] ppid=6008 vsize=49956 CPUtime=17.47
/proc/6011/stat : 6011 (bmo-pblex32) R 6008 6008 25521 34816 2180 4202496 15956 0 0 0 1600 147 0 0 25 0 1 0 901330087 51154944 12168 1283457024 134512640 135887319 4289887680 18446744073709551615 134605916 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6011/statm: 12489 12168 144 336 0 12151 0
Current children cumulated CPU time (s) 19.9
Current children cumulated vsize (KiB) 52528

[startup+20.8094 s]
/proc/loadavg: 1.08 1.07 1.02 2/40 6011
/proc/meminfo: memFree=367636/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=2.43
/proc/6008/stat : 6008 (cudf2pbo4user-1) S 6007 6008 25521 34816 2180 4202496 404 15777 0 0 0 0 198 45 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
[pid=6011] ppid=6008 vsize=50228 CPUtime=18.27
/proc/6011/stat : 6011 (bmo-pblex32) R 6008 6008 25521 34816 2180 4202496 16007 0 0 0 1677 150 0 0 25 0 1 0 901330087 51433472 12217 1283457024 134512640 135887319 4289887680 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/6011/statm: 12557 12217 144 336 0 12219 0
Current children cumulated CPU time (s) 20.7
Current children cumulated vsize (KiB) 52800

[startup+21.2109 s]
/proc/loadavg: 1.08 1.06 1.02 2/40 6011
/proc/meminfo: memFree=367512/1048576 swapFree=2095372/2097144
[pid=6008] ppid=6007 vsize=2572 CPUtime=21.09
/proc/6008/stat : 6008 (cudf2pbo4user-1) R 6007 6008 25521 34816 2180 4202496 423 31788 0 0 0 0 1912 197 18 0 1 0 901329841 2633728 282 1283457024 134512640 135304128 4288050016 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/6008/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 21.09
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 21.2691
CPU time (s): 21.1733
CPU user time (s): 19.2012
CPU system time (s): 1.97212
CPU usage (%): 99.5497
Max. virtual memory (cumulated for all children) (KiB): 64908

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 19.2012
system time used= 1.97212
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 34177
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= 22
involuntary context switches= 3051

runsolver used 0 second user time and 0 second system time

The end