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/rand0695fb.cudf.impossible.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/impossible//rand0695fb.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand0695fb.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: 1.06 0.88 0.49 3/39 9321
/proc/meminfo: memFree=28856/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=0
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 18 0 1 0 892236276 2633728 279 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 279 238 194 0 29 0
[pid=9321] ppid=9320 vsize=2572 CPUtime=0
/proc/9321/stat : 9321 (cudf2pbo4parano) D 9320 9320 9023 34817 9081 4202560 80 0 0 0 0 0 0 0 18 0 1 0 892236276 2633728 104 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 0 0 0 18446744071564252162 0 0 17 0 0 0 0
/proc/9321/statm: 643 104 62 194 0 29 0

[startup+0.140716 s]
/proc/loadavg: 1.06 0.88 0.49 3/39 9321
/proc/meminfo: memFree=28856/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=0
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 18 0 1 0 892236276 2633728 279 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 279 238 194 0 29 0
[pid=9321] ppid=9320 vsize=6992 CPUtime=0.12
/proc/9321/stat : 9321 (cudf_msu32) R 9320 9320 9023 34817 9081 4202496 1571 0 0 0 12 0 0 0 25 0 1 0 892236276 7159808 1463 1283457024 134512640 136125367 4291610448 18446744073709551615 134717908 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9321/statm: 1748 1463 143 394 0 1352 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 9564

[startup+0.209604 s]
/proc/loadavg: 1.06 0.88 0.49 3/39 9321
/proc/meminfo: memFree=28856/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=0
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 18 0 1 0 892236276 2633728 279 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 279 238 194 0 29 0
[pid=9321] ppid=9320 vsize=9500 CPUtime=0.16
/proc/9321/stat : 9321 (cudf_msu32) D 9320 9320 9023 34817 9081 4202496 2197 0 0 0 16 0 0 0 25 0 1 0 892236276 9728000 2089 1283457024 134512640 136125367 4291610448 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/9321/statm: 2375 2089 143 394 0 1979 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 12072

[startup+0.30473 s]
/proc/loadavg: 1.06 0.88 0.49 3/39 9321
/proc/meminfo: memFree=28856/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=0
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 18 0 1 0 892236276 2633728 279 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 279 238 194 0 29 0
[pid=9321] ppid=9320 vsize=12956 CPUtime=0.25
/proc/9321/stat : 9321 (cudf_msu32) R 9320 9320 9023 34817 9081 4202496 3037 0 0 0 25 0 0 0 25 0 1 0 892236276 13266944 2929 1283457024 134512640 136125367 4291610448 18446744073709551615 134738376 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9321/statm: 3239 2929 144 394 0 2843 0
Current children cumulated CPU time (s) 0.25
Current children cumulated vsize (KiB) 15528

[startup+0.704735 s]
/proc/loadavg: 1.06 0.88 0.49 3/39 9321
/proc/meminfo: memFree=28856/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=0
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 18 0 1 0 892236276 2633728 279 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 279 238 194 0 29 0
[pid=9321] ppid=9320 vsize=24900 CPUtime=0.58
/proc/9321/stat : 9321 (cudf_msu32) R 9320 9320 9023 34817 9081 4202496 6025 0 0 0 58 0 0 0 25 0 1 0 892236276 25497600 5917 1283457024 134512640 136125367 4291610448 18446744073709551615 134738395 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9321/statm: 6225 5917 144 394 0 5829 0
Current children cumulated CPU time (s) 0.58
Current children cumulated vsize (KiB) 27472

[startup+1.5048 s]
/proc/loadavg: 1.06 0.88 0.49 1/40 9322
/proc/meminfo: memFree=5212/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=0
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 18 0 1 0 892236276 2633728 279 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 279 238 194 0 29 0
[pid=9321] ppid=9320 vsize=44760 CPUtime=1.24
/proc/9321/stat : 9321 (cudf_msu32) R 9320 9320 9023 34817 9081 4202496 11060 0 0 0 120 4 0 0 25 0 1 0 892236276 45834240 10903 1283457024 134512640 136125367 4291610448 18446744073709551615 135549870 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9321/statm: 11190 10903 144 394 0 10794 0
Current children cumulated CPU time (s) 1.24
Current children cumulated vsize (KiB) 47332

[startup+3.10498 s]
/proc/loadavg: 1.06 0.88 0.49 2/40 9322
/proc/meminfo: memFree=5856/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=2.06
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 404 14684 0 0 0 0 176 30 20 0 1 0 892236276 2633728 282 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 2.06
Current children cumulated vsize (KiB) 2572
heavy processes:

[startup+6.3061 s]
/proc/loadavg: 1.05 0.88 0.49 2/40 9323
/proc/meminfo: memFree=39832/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=2.06
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 404 14684 0 0 0 0 176 30 20 0 1 0 892236276 2633728 282 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 282 241 194 0 29 0
[pid=9323] ppid=9320 vsize=25236 CPUtime=3.87
/proc/9323/stat : 9323 (bmo-pblex32) R 9320 9320 9023 34817 9081 4202496 7531 0 0 0 312 75 0 0 25 0 1 0 892236510 25841664 6026 1283457024 134512640 135887319 4288926928 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9323/statm: 6309 6026 144 336 0 5971 0
Current children cumulated CPU time (s) 5.93
Current children cumulated vsize (KiB) 27808

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

[startup+6.40613 s]
/proc/loadavg: 1.05 0.88 0.49 2/40 9323
/proc/meminfo: memFree=39832/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=2.06
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 404 14684 0 0 0 0 176 30 20 0 1 0 892236276 2633728 282 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 282 241 194 0 29 0
[pid=9323] ppid=9320 vsize=25368 CPUtime=3.97
/proc/9323/stat : 9323 (bmo-pblex32) R 9320 9320 9023 34817 9081 4202496 7552 0 0 0 322 75 0 0 25 0 1 0 892236510 25976832 6045 1283457024 134512640 135887319 4288926928 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9323/statm: 6342 6045 144 336 0 6004 0
Current children cumulated CPU time (s) 6.03
Current children cumulated vsize (KiB) 27940

[startup+8.00678 s]
/proc/loadavg: 1.05 0.88 0.49 3/40 9323
/proc/meminfo: memFree=38220/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=2.06
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 404 14684 0 0 0 0 176 30 20 0 1 0 892236276 2633728 282 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 282 241 194 0 29 0
[pid=9323] ppid=9320 vsize=26480 CPUtime=5.57
/proc/9323/stat : 9323 (bmo-pblex32) R 9320 9320 9023 34817 9081 4202496 7862 0 0 0 455 102 0 0 25 0 1 0 892236510 27115520 6346 1283457024 134512640 135887319 4288926928 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9323/statm: 6620 6346 144 336 0 6282 0
Current children cumulated CPU time (s) 7.63
Current children cumulated vsize (KiB) 29052

[startup+8.80709 s]
/proc/loadavg: 1.05 0.88 0.49 2/40 9323
/proc/meminfo: memFree=37476/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=2.06
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 404 14684 0 0 0 0 176 30 20 0 1 0 892236276 2633728 282 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 282 241 194 0 29 0
[pid=9323] ppid=9320 vsize=27172 CPUtime=6.37
/proc/9323/stat : 9323 (bmo-pblex32) R 9320 9320 9023 34817 9081 4202496 8028 0 0 0 515 122 0 0 25 0 1 0 892236510 27824128 6500 1283457024 134512640 135887319 4288926928 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9323/statm: 6793 6500 144 336 0 6455 0
Current children cumulated CPU time (s) 8.43
Current children cumulated vsize (KiB) 29744

[startup+9.6074 s]
/proc/loadavg: 1.05 0.88 0.49 2/40 9323
/proc/meminfo: memFree=37476/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=2.06
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 404 14684 0 0 0 0 176 30 20 0 1 0 892236276 2633728 282 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 282 241 194 0 29 0
[pid=9323] ppid=9320 vsize=27724 CPUtime=7.17
/proc/9323/stat : 9323 (bmo-pblex32) R 9320 9320 9023 34817 9081 4202496 8221 0 0 0 587 130 0 0 25 0 1 0 892236510 28389376 6659 1283457024 134512640 135887319 4288926928 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9323/statm: 6931 6659 144 336 0 6593 0
Current children cumulated CPU time (s) 9.23
Current children cumulated vsize (KiB) 30296

[startup+9.80748 s]
/proc/loadavg: 1.05 0.88 0.49 2/40 9323
/proc/meminfo: memFree=37476/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=2.06
/proc/9320/stat : 9320 (cudf2pbo4parano) S 9319 9320 9023 34817 9081 4202496 404 14684 0 0 0 0 176 30 20 0 1 0 892236276 2633728 282 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9320/statm: 643 282 241 194 0 29 0
[pid=9323] ppid=9320 vsize=27864 CPUtime=7.36
/proc/9323/stat : 9323 (bmo-pblex32) R 9320 9320 9023 34817 9081 4202496 8263 0 0 0 602 134 0 0 25 0 1 0 892236510 28532736 6699 1283457024 134512640 135887319 4288926928 18446744073709551615 134598344 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9323/statm: 6966 6699 144 336 0 6628 0
Current children cumulated CPU time (s) 9.42
Current children cumulated vsize (KiB) 30436

[startup+9.90752 s]
/proc/loadavg: 1.05 0.89 0.50 4/41 9325
/proc/meminfo: memFree=59408/1048576 swapFree=2095372/2097144
[pid=9320] ppid=9319 vsize=2572 CPUtime=9.49
/proc/9320/stat : 9320 (cudf2pbo4parano) R 9319 9320 9023 34817 9081 4202496 423 22960 0 0 0 0 784 165 18 0 1 0 892236276 2633728 282 1283457024 134512640 135304128 4288459744 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/9320/statm: 643 282 241 194 0 29 0
[pid=9324] ppid=9320 vsize=1952 CPUtime=0
/proc/9324/stat : 9324 (grep) S 9320 9320 9023 34817 9081 4202496 352 0 0 0 0 0 0 0 18 0 1 0 892237262 1998848 222 1283457024 134512640 134613452 4292710512 18446744073709551615 4294960130 0 0 0 0 18446744071564457842 0 0 17 0 0 0 0
/proc/9324/statm: 488 222 136 25 0 105 0
[pid=9325] ppid=9320 vsize=8588 CPUtime=0.04
/proc/9325/stat : 9325 (sc.py) R 9320 9320 9023 34817 9081 4202496 1400 0 0 0 4 0 0 0 18 0 1 0 892237262 8794112 1215 1283457024 134512640 136476992 4294738528 18446744073709551615 135120252 0 0 16781312 2 0 0 0 17 0 0 0 0
/proc/9325/statm: 2147 1215 481 480 0 731 0
Current children cumulated CPU time (s) 9.53
Current children cumulated vsize (KiB) 13112

Child status: 0
Real time (s): 9.93088
CPU time (s): 9.5606
CPU user time (s): 7.90049
CPU system time (s): 1.6601
CPU usage (%): 96.2714
Max. virtual memory (cumulated for all children) (KiB): 61708

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.90049
system time used= 1.6601
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25329
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= 77
involuntary context switches= 3873

runsolver used 0 second user time and 0 second system time

The end