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/cudf2msu4user-1.0/rand7141b1.cudf.impossible.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/impossible//rand7141b1.cudf /home/misc2010/tmp/201012091704/cudf2msu4user-1.0/rand7141b1.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.01 1.01 1.00 4/38 5062
/proc/meminfo: memFree=424800/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=2176 CPUtime=0
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 295 0 0 0 0 0 0 0 25 0 1 0 901166716 2228224 233 1283457024 134512640 136120023 4293075008 18446744073709551615 135171472 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 544 233 140 393 0 149 0

[startup+0.167434 s]
/proc/loadavg: 1.01 1.01 1.00 4/38 5062
/proc/meminfo: memFree=424800/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=8692 CPUtime=0.16
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 1934 0 0 0 16 0 0 0 25 0 1 0 901166716 8900608 1872 1283457024 134512640 136120023 4293075008 18446744073709551615 134721269 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 2173 1872 141 393 0 1778 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 11264

[startup+0.207438 s]
/proc/loadavg: 1.01 1.01 1.00 4/38 5062
/proc/meminfo: memFree=424800/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=10012 CPUtime=0.2
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 2278 0 0 0 20 0 0 0 25 0 1 0 901166716 10252288 2216 1283457024 134512640 136120023 4293075008 18446744073709551615 134711831 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 2503 2216 141 393 0 2108 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12584

[startup+0.307464 s]
/proc/loadavg: 1.01 1.01 1.00 4/38 5062
/proc/meminfo: memFree=424800/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=13508 CPUtime=0.3
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 3132 0 0 0 28 2 0 0 25 0 1 0 901166716 13832192 3070 1283457024 134512640 136120023 4293075008 18446744073709551615 134711968 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 3377 3070 142 393 0 2982 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16080

[startup+0.707563 s]
/proc/loadavg: 1.01 1.01 1.00 4/38 5062
/proc/meminfo: memFree=424800/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=25188 CPUtime=0.7
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 6066 0 0 0 66 4 0 0 25 0 1 0 901166716 25792512 6004 1283457024 134512640 136120023 4293075008 18446744073709551615 134711970 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 6297 6004 142 393 0 5902 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27760

[startup+1.50777 s]
/proc/loadavg: 1.01 1.01 1.00 2/39 5063
/proc/meminfo: memFree=390904/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=45444 CPUtime=1.5
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 11166 0 0 0 146 4 0 0 25 0 1 0 901166716 46534656 11055 1283457024 134512640 136120023 4293075008 18446744073709551615 135171584 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 11361 11055 142 393 0 10966 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 48016

[startup+3.10821 s]
/proc/loadavg: 1.01 1.01 1.00 2/39 5063
/proc/meminfo: memFree=324192/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=102436 CPUtime=3.1
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 25782 0 0 0 300 10 0 0 25 0 1 0 901166716 104894464 25353 1283457024 134512640 136120023 4293075008 18446744073709551615 135524602 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 25609 25353 179 393 0 25214 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 105008

[startup+6.30916 s]
/proc/loadavg: 1.01 1.01 1.00 2/39 5063
/proc/meminfo: memFree=324068/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=102436 CPUtime=6.3
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 25784 0 0 0 620 10 0 0 25 0 1 0 901166716 104894464 25355 1283457024 134512640 136120023 4293075008 18446744073709551615 135524336 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 25609 25355 181 393 0 25214 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 105008

[startup+12.7107 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=322580/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=104028 CPUtime=12.68
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 26188 0 0 0 1258 10 0 0 25 0 1 0 901166716 106524672 25748 1283457024 134512640 136120023 4293075008 18446744073709551615 135511805 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 26007 25748 185 393 0 25612 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 106600

[startup+25.5048 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=322456/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=104028 CPUtime=25.46
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 26188 0 0 0 2534 12 0 0 25 0 1 0 901166716 106524672 25748 1283457024 134512640 136120023 4293075008 18446744073709551615 135524116 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 26007 25748 185 393 0 25612 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 106600

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

[startup+25.6049 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=322456/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=104028 CPUtime=25.56
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 26188 0 0 0 2544 12 0 0 25 0 1 0 901166716 106524672 25748 1283457024 134512640 136120023 4293075008 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 26007 25748 185 393 0 25612 0
Current children cumulated CPU time (s) 25.56
Current children cumulated vsize (KiB) 106600

[startup+32.0066 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=322456/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=104028 CPUtime=31.97
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 26188 0 0 0 3183 14 0 0 25 0 1 0 901166716 106524672 25748 1283457024 134512640 136120023 4293075008 18446744073709551615 134840147 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 26007 25748 185 393 0 25612 0
Current children cumulated CPU time (s) 31.97
Current children cumulated vsize (KiB) 106600

[startup+35.2074 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=316132/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=110376 CPUtime=35.17
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 27793 0 0 0 3503 14 0 0 25 0 1 0 901166716 113025024 27349 1283457024 134512640 136120023 4293075008 18446744073709551615 134863393 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 27594 27349 185 393 0 27199 0
Current children cumulated CPU time (s) 35.17
Current children cumulated vsize (KiB) 112948

[startup+38.4084 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=316008/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=111168 CPUtime=38.36
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 29560 0 0 0 3821 15 0 0 25 0 1 0 901166716 113836032 27537 1283457024 134512640 136120023 4293075008 18446744073709551615 134871727 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 27792 27537 185 393 0 27397 0
Current children cumulated CPU time (s) 38.36
Current children cumulated vsize (KiB) 113740

[startup+40.0089 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=315264/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=111168 CPUtime=39.96
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 29560 0 0 0 3981 15 0 0 25 0 1 0 901166716 113836032 27537 1283457024 134512640 136120023 4293075008 18446744073709551615 135524329 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 27792 27537 185 393 0 27397 0
Current children cumulated CPU time (s) 39.96
Current children cumulated vsize (KiB) 113740

[startup+40.409 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=315264/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=111168 CPUtime=40.35
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 29560 0 0 0 4020 15 0 0 25 0 1 0 901166716 113836032 27537 1283457024 134512640 136120023 4293075008 18446744073709551615 134831637 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 27792 27537 185 393 0 27397 0
Current children cumulated CPU time (s) 40.35
Current children cumulated vsize (KiB) 113740

[startup+40.6091 s]
/proc/loadavg: 1.00 1.01 1.00 2/39 5063
/proc/meminfo: memFree=315264/1048576 swapFree=2095372/2097144
[pid=5061] ppid=5060 vsize=2572 CPUtime=0
/proc/5061/stat : 5061 (cudf2msu4user-1) S 5060 5061 25521 34816 2180 4202496 381 0 0 0 0 0 0 0 18 0 1 0 901166716 2633728 277 1283457024 134512640 135304128 4287021664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5061/statm: 643 277 237 194 0 29 0
[pid=5062] ppid=5061 vsize=104028 CPUtime=40.55
/proc/5062/stat : 5062 (cudf_msu32) R 5061 5061 25521 34816 2180 4202496 29575 0 0 0 4040 15 0 0 25 0 1 0 901166716 106524672 25785 1283457024 134512640 136120023 4293075008 18446744073709551615 134694119 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/5062/statm: 26007 25785 200 393 0 25612 0
Current children cumulated CPU time (s) 40.55
Current children cumulated vsize (KiB) 106600

Child status: 0
Real time (s): 40.6656
CPU time (s): 40.6145
CPU user time (s): 40.4465
CPU system time (s): 0.16801
CPU usage (%): 99.8744
Max. virtual memory (cumulated for all children) (KiB): 113740

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 40.4465
system time used= 0.16801
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 29967
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= 3
involuntary context switches= 532

runsolver used 0 second user time and 0 second system time

The end