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/201012091434/cudf2msu4user-1.0/randfa4522.cudf.impossible.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/impossible//randfa4522.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/randfa4522.cudf.impossible.result -changed,-removed,-unmet_recommends,-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.26 1.10 1.04 5/39 32665
/proc/meminfo: memFree=402348/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=2568 CPUtime=0.02
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 395 0 0 0 2 0 0 0 25 0 1 0 900567203 2629632 334 1283457024 134512640 136120023 4293017648 18446744073709551615 135394322 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 642 334 140 393 0 247 0

[startup+0.185376 s]
/proc/loadavg: 1.26 1.10 1.04 5/39 32665
/proc/meminfo: memFree=402348/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=9216 CPUtime=0.18
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 2064 0 0 0 17 1 0 0 25 0 1 0 900567203 9437184 2003 1283457024 134512640 136120023 4293017648 18446744073709551615 134711848 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 2304 2003 141 393 0 1909 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 11788

[startup+0.205379 s]
/proc/loadavg: 1.26 1.10 1.04 5/39 32665
/proc/meminfo: memFree=402348/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=9876 CPUtime=0.2
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 2230 0 0 0 19 1 0 0 25 0 1 0 900567203 10113024 2169 1283457024 134512640 136120023 4293017648 18446744073709551615 134712142 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 2469 2169 141 393 0 2074 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12448

[startup+0.3054 s]
/proc/loadavg: 1.26 1.10 1.04 5/39 32665
/proc/meminfo: memFree=402348/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=13372 CPUtime=0.3
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 3097 0 0 0 29 1 0 0 25 0 1 0 900567203 13692928 3036 1283457024 134512640 136120023 4293017648 18446744073709551615 134598107 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 3343 3036 142 393 0 2948 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15944

[startup+0.705484 s]
/proc/loadavg: 1.26 1.10 1.04 5/39 32665
/proc/meminfo: memFree=402348/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=24920 CPUtime=0.7
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 6000 0 0 0 67 3 0 0 25 0 1 0 900567203 25518080 5939 1283457024 134512640 136120023 4293017648 18446744073709551615 134732904 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 6230 5939 142 393 0 5835 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27492

[startup+1.50564 s]
/proc/loadavg: 1.24 1.10 1.04 2/40 32666
/proc/meminfo: memFree=369396/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=45044 CPUtime=1.49
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 11089 0 0 0 144 5 0 0 25 0 1 0 900567203 46125056 10979 1283457024 134512640 136120023 4293017648 18446744073709551615 134721244 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 11261 10979 142 393 0 10866 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 47616

[startup+3.10621 s]
/proc/loadavg: 1.24 1.10 1.04 2/40 32666
/proc/meminfo: memFree=279620/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=139340 CPUtime=3.09
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 35167 0 0 0 296 13 0 0 25 0 1 0 900567203 142684160 34551 1283457024 134512640 136120023 4293017648 18446744073709551615 134780956 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 34835 34551 178 393 0 34440 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 141912

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

[startup+3.20624 s]
/proc/loadavg: 1.24 1.10 1.04 2/40 32666
/proc/meminfo: memFree=279620/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=139340 CPUtime=3.19
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 35167 0 0 0 306 13 0 0 25 0 1 0 900567203 142684160 34551 1283457024 134512640 136120023 4293017648 18446744073709551615 134831661 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 34835 34551 178 393 0 34440 0
Current children cumulated CPU time (s) 3.19
Current children cumulated vsize (KiB) 141912

[startup+4.0065 s]
/proc/loadavg: 1.24 1.10 1.04 2/40 32666
/proc/meminfo: memFree=264864/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=139340 CPUtime=3.99
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 35174 0 0 0 386 13 0 0 25 0 1 0 900567203 142684160 34558 1283457024 134512640 136120023 4293017648 18446744073709551615 134867666 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 34835 34558 185 393 0 34440 0
Current children cumulated CPU time (s) 3.99
Current children cumulated vsize (KiB) 141912

[startup+4.80677 s]
/proc/loadavg: 1.24 1.10 1.04 2/40 32666
/proc/meminfo: memFree=264864/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=139736 CPUtime=4.8
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 35298 0 0 0 467 13 0 0 25 0 1 0 900567203 143089664 34682 1283457024 134512640 136120023 4293017648 18446744073709551615 134780948 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 34934 34682 185 393 0 34539 0
Current children cumulated CPU time (s) 4.8
Current children cumulated vsize (KiB) 142308

[startup+5.00682 s]
/proc/loadavg: 1.24 1.10 1.04 2/40 32666
/proc/meminfo: memFree=264864/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=139736 CPUtime=5
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202496 35298 0 0 0 487 13 0 0 25 0 1 0 900567203 143089664 34682 1283457024 134512640 136120023 4293017648 18446744073709551615 135530294 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 34934 34682 185 393 0 34539 0
Current children cumulated CPU time (s) 5
Current children cumulated vsize (KiB) 142308

[startup+5.10915 s]
/proc/loadavg: 1.24 1.10 1.04 2/40 32666
/proc/meminfo: memFree=264864/1048576 swapFree=2095372/2097144
[pid=32664] ppid=32663 vsize=2572 CPUtime=0
/proc/32664/stat : 32664 (cudf2msu4user-1) S 32663 32664 25521 34816 25544 4202496 379 0 0 0 0 0 0 0 18 0 1 0 900567203 2633728 276 1283457024 134512640 135304128 4291059248 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32664/statm: 643 276 237 194 0 29 0
[pid=32665] ppid=32664 vsize=0 CPUtime=5.1
/proc/32665/stat : 32665 (cudf_msu32) R 32664 32664 25521 34816 25544 4202500 35314 0 0 0 494 16 0 0 25 0 1 0 900567203 0 0 1283457024 0 0 0 0 0 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32665/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 5.1
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 5.11238
CPU time (s): 5.10832
CPU user time (s): 4.94031
CPU system time (s): 0.16801
CPU usage (%): 99.9205
Max. virtual memory (cumulated for all children) (KiB): 142308

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.94031
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= 35703
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= 103

runsolver used 0 second user time and 0 second system time

The end