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/218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/debian-dudf//218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf.debian-dudf.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.22 1.03 0.79 4/38 26578
/proc/meminfo: memFree=664248/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=2308 CPUtime=0
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 336 0 0 0 0 0 0 0 25 0 1 0 899958646 2363392 275 1283457024 134512640 136120023 4293658784 18446744073709551615 135544350 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 577 275 140 393 0 182 0

[startup+0.161496 s]
/proc/loadavg: 1.22 1.03 0.79 4/38 26578
/proc/meminfo: memFree=664248/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=8044 CPUtime=0.15
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 1776 0 0 0 14 1 0 0 25 0 1 0 899958646 8237056 1715 1283457024 134512640 136120023 4293658784 18446744073709551615 135589790 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 2011 1715 140 393 0 1616 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 10616

[startup+0.211509 s]
/proc/loadavg: 1.22 1.03 0.79 4/38 26578
/proc/meminfo: memFree=664248/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=9760 CPUtime=0.2
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 2206 0 0 0 19 1 0 0 25 0 1 0 899958646 9994240 2145 1283457024 134512640 136120023 4293658784 18446744073709551615 134711996 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 2440 2145 140 393 0 2045 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12332

[startup+0.311557 s]
/proc/loadavg: 1.22 1.03 0.79 4/38 26578
/proc/meminfo: memFree=664248/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=12728 CPUtime=0.3
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 2960 0 0 0 29 1 0 0 25 0 1 0 899958646 13033472 2899 1283457024 134512640 136120023 4293658784 18446744073709551615 134711959 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 3182 2899 141 393 0 2787 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15300

[startup+0.711641 s]
/proc/loadavg: 1.22 1.03 0.79 4/38 26578
/proc/meminfo: memFree=664248/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=23616 CPUtime=0.7
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 5674 0 0 0 68 2 0 0 25 0 1 0 899958646 24182784 5613 1283457024 134512640 136120023 4293658784 18446744073709551615 134734231 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 5904 5613 141 393 0 5509 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26188

[startup+1.51186 s]
/proc/loadavg: 1.20 1.03 0.79 2/39 26579
/proc/meminfo: memFree=633032/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=50752 CPUtime=1.5
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 12853 0 0 0 146 4 0 0 25 0 1 0 899958646 51970048 12399 1283457024 134512640 136120023 4293658784 18446744073709551615 135524851 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 12688 12399 152 393 0 12293 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 53324

[startup+3.10237 s]
/proc/loadavg: 1.20 1.03 0.79 2/39 26579
/proc/meminfo: memFree=549828/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=116532 CPUtime=3.1
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 29462 0 0 0 298 12 0 0 25 0 1 0 899958646 119328768 28834 1283457024 134512640 136120023 4293658784 18446744073709551615 134863582 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 29133 28834 181 393 0 28738 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 119104

[startup+6.30351 s]
/proc/loadavg: 1.20 1.03 0.79 2/39 26579
/proc/meminfo: memFree=549332/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=117320 CPUtime=6.3
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 29726 0 0 0 618 12 0 0 25 0 1 0 899958646 120135680 29065 1283457024 134512640 136120023 4293658784 18446744073709551615 134831748 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 29330 29065 185 393 0 28935 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 119892

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

[startup+6.41355 s]
/proc/loadavg: 1.20 1.03 0.79 2/39 26579
/proc/meminfo: memFree=549332/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=117320 CPUtime=6.41
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 29726 0 0 0 629 12 0 0 25 0 1 0 899958646 120135680 29065 1283457024 134512640 136120023 4293658784 18446744073709551615 134863531 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 29330 29065 185 393 0 28935 0
Current children cumulated CPU time (s) 6.41
Current children cumulated vsize (KiB) 119892

[startup+8.01398 s]
/proc/loadavg: 1.18 1.03 0.79 2/39 26579
/proc/meminfo: memFree=548844/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=117320 CPUtime=8.01
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 29726 0 0 0 789 12 0 0 25 0 1 0 899958646 120135680 29065 1283457024 134512640 136120023 4293658784 18446744073709551615 134872366 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 29330 29065 185 393 0 28935 0
Current children cumulated CPU time (s) 8.01
Current children cumulated vsize (KiB) 119892

[startup+8.81435 s]
/proc/loadavg: 1.18 1.03 0.79 2/39 26579
/proc/meminfo: memFree=548596/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=117584 CPUtime=8.81
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 29798 0 0 0 869 12 0 0 25 0 1 0 899958646 120406016 29137 1283457024 134512640 136120023 4293658784 18446744073709551615 134863525 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 29396 29137 185 393 0 29001 0
Current children cumulated CPU time (s) 8.81
Current children cumulated vsize (KiB) 120156

[startup+9.2145 s]
/proc/loadavg: 1.18 1.03 0.79 2/39 26579
/proc/meminfo: memFree=548596/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=117584 CPUtime=9.21
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 29798 0 0 0 909 12 0 0 25 0 1 0 899958646 120406016 29137 1283457024 134512640 136120023 4293658784 18446744073709551615 134891712 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 29396 29137 185 393 0 29001 0
Current children cumulated CPU time (s) 9.21
Current children cumulated vsize (KiB) 120156

[startup+9.31453 s]
/proc/loadavg: 1.18 1.03 0.79 2/39 26579
/proc/meminfo: memFree=548596/1048576 swapFree=2095372/2097144
[pid=26577] ppid=26576 vsize=2572 CPUtime=0
/proc/26577/stat : 26577 (cudf2msu4user-1) S 26576 26577 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 899958646 2633728 277 1283457024 134512640 135304128 4293716096 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26577/statm: 643 277 237 194 0 29 0
[pid=26578] ppid=26577 vsize=117192 CPUtime=9.29
/proc/26578/stat : 26578 (cudf_msu32) R 26577 26577 25521 34816 25544 4202496 29813 0 0 0 916 13 0 0 25 0 1 0 899958646 120004608 29054 1283457024 134512640 136120023 4293658784 18446744073709551615 134587332 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/26578/statm: 29298 29054 200 393 0 28903 0
Current children cumulated CPU time (s) 9.29
Current children cumulated vsize (KiB) 119764

Child status: 0
Real time (s): 9.34563
CPU time (s): 9.34458
CPU user time (s): 9.18057
CPU system time (s): 0.16401
CPU usage (%): 99.9889
Max. virtual memory (cumulated for all children) (KiB): 120156

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.18057
system time used= 0.16401
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 30205
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= 156

runsolver used 0 second user time and 0 second system time

The end