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/201012070034/aptitude-trendy-1.0/103c9978-5408-11df-9bc1-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/debian-dudf//103c9978-5408-11df-9bc1-00163e7a6f5e.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/103c9978-5408-11df-9bc1-00163e7a6f5e.cudf.debian-dudf.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: 0.85 0.91 0.60 3/44 4514
/proc/meminfo: memFree=534644/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2576 CPUtime=0
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 452 759 0 0 0 0 0 0 25 0 1 0 877587092 2637824 276 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 644 276 235 194 0 30 0
[pid=4514] ppid=4509 vsize=1640 CPUtime=0
/proc/4514/stat : 4514 (mkdir) R 4509 4509 4159 34819 4229 4194304 137 0 0 0 0 0 0 0 25 0 1 0 877587093 1679360 74 1283457024 134512640 134551716 4291450688 18446744073709551615 4159756827 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4514/statm: 410 74 57 10 0 11 0

[startup+0.181449 s]
/proc/loadavg: 0.85 0.91 0.60 3/44 4514
/proc/meminfo: memFree=534644/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2584 CPUtime=0.02
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 566 1862 0 0 0 0 0 2 25 0 1 0 877587092 2646016 283 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.20754 s]
/proc/loadavg: 0.85 0.91 0.60 3/44 4514
/proc/meminfo: memFree=534644/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2584 CPUtime=0.02
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 566 1862 0 0 0 0 0 2 25 0 1 0 877587092 2646016 283 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.30756 s]
/proc/loadavg: 0.85 0.91 0.60 3/44 4514
/proc/meminfo: memFree=534644/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2584 CPUtime=0.02
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 566 1862 0 0 0 0 0 2 25 0 1 0 877587092 2646016 283 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.707621 s]
/proc/loadavg: 0.85 0.91 0.60 3/44 4514
/proc/meminfo: memFree=534644/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2584 CPUtime=0.02
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 566 1862 0 0 0 0 0 2 25 0 1 0 877587092 2646016 283 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+1.50776 s]
/proc/loadavg: 0.85 0.91 0.60 2/45 4520
/proc/meminfo: memFree=503444/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2584 CPUtime=0.02
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 566 1862 0 0 0 0 0 2 25 0 1 0 877587092 2646016 283 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 646 283 240 194 0 32 0
[pid=4520] ppid=4509 vsize=31200 CPUtime=1.46
/proc/4520/stat : 4520 (cudftodeb.nativ) R 4509 4509 4159 34819 4229 4202496 7332 0 3 0 144 2 0 0 25 0 1 0 877587096 31948800 7262 1283457024 134512640 135004320 4291750080 18446744073709551615 134950940 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4520/statm: 7800 7262 225 121 0 7192 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 33784

[startup+3.10809 s]
/proc/loadavg: 0.85 0.91 0.60 2/45 4520
/proc/meminfo: memFree=479512/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2584 CPUtime=0.02
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 566 1862 0 0 0 0 0 2 25 0 1 0 877587092 2646016 283 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 646 283 240 194 0 32 0
[pid=4520] ppid=4509 vsize=60500 CPUtime=3.06
/proc/4520/stat : 4520 (cudftodeb.nativ) R 4509 4509 4159 34819 4229 4202496 14625 0 3 0 300 6 0 0 25 0 1 0 877587096 61952000 14555 1283457024 134512640 135004320 4291750080 18446744073709551615 134950944 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4520/statm: 15125 14555 237 121 0 14517 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 63084

[startup+6.3075 s]
/proc/loadavg: 0.87 0.91 0.60 2/45 4531
/proc/meminfo: memFree=477076/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2592 CPUtime=3.35
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 696 19664 0 4 0 0 322 13 18 0 1 0 877587092 2654208 294 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 648 294 249 194 0 34 0
[pid=4530] ppid=4509 vsize=47280 CPUtime=1.03
/proc/4530/stat : 4530 (aptitude) R 4509 4509 4159 34819 4229 4202496 8998 241 224 0 96 7 0 0 19 0 2 0 877587507 48414720 6084 1283457024 134512640 137933492 4294314384 18446744073709551615 4159291940 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/4530/statm: 11820 6084 3714 836 0 6449 0
Current children cumulated CPU time (s) 4.38
Current children cumulated vsize (KiB) 49872
heavy processes:

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

[startup+6.40751 s]
/proc/loadavg: 0.87 0.91 0.60 2/46 4533
/proc/meminfo: memFree=466324/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2592 CPUtime=3.35
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 696 19664 0 4 0 0 322 13 18 0 1 0 877587092 2654208 294 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 648 294 249 194 0 34 0
[pid=4530] ppid=4509 vsize=47432 CPUtime=1.13
/proc/4530/stat : 4530 (aptitude) R 4509 4509 4159 34819 4229 4202496 9315 651 224 0 105 8 0 0 20 0 2 0 877587507 48570368 6137 1283457024 134512640 137933492 4294314384 18446744073709551615 135234610 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/4530/statm: 11858 6137 3749 836 0 6487 0
[pid=4530/tid=4532] ppid=4509 vsize=47432 CPUtime=0
/proc/4530/task/4532/stat : 4532 (aptitude) S 4509 4509 4159 34819 4229 4202560 5 651 0 0 0 0 0 0 15 0 2 0 877587682 48570368 6137 1283457024 134512640 137933492 4294314384 18446744073709551615 4294960130 0 134217728 4096 0 18446612133395920000 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.48
Current children cumulated vsize (KiB) 50024

[startup+8.00437 s]
/proc/loadavg: 0.88 0.91 0.60 2/45 4536
/proc/meminfo: memFree=462128/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2592 CPUtime=5.08
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 722 32326 0 232 0 0 487 21 18 0 1 0 877587092 2654208 294 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 648 294 249 194 0 34 0
[pid=4536] ppid=4509 vsize=21732 CPUtime=0.94
/proc/4536/stat : 4536 (aptsolutions.na) R 4509 4509 4159 34819 4229 4202496 5043 0 3 0 90 4 0 0 21 0 1 0 877587796 22253568 4935 1283457024 134512640 134971616 4294733440 18446744073709551615 134606839 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4536/statm: 5433 4935 204 113 0 4835 0
Current children cumulated CPU time (s) 6.02
Current children cumulated vsize (KiB) 24324

[startup+8.40444 s]
/proc/loadavg: 0.88 0.91 0.60 2/45 4536
/proc/meminfo: memFree=462128/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2592 CPUtime=5.08
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 722 32326 0 232 0 0 487 21 18 0 1 0 877587092 2654208 294 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 648 294 249 194 0 34 0
[pid=4536] ppid=4509 vsize=29420 CPUtime=1.34
/proc/4536/stat : 4536 (aptsolutions.na) R 4509 4509 4159 34819 4229 4202496 6964 0 3 0 130 4 0 0 22 0 1 0 877587796 30126080 6856 1283457024 134512640 134971616 4294733440 18446744073709551615 134954131 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4536/statm: 7355 6856 204 113 0 6757 0
Current children cumulated CPU time (s) 6.42
Current children cumulated vsize (KiB) 32012

[startup+8.802 s]
/proc/loadavg: 0.88 0.91 0.60 2/45 4536
/proc/meminfo: memFree=440864/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2592 CPUtime=5.08
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 722 32326 0 232 0 0 487 21 18 0 1 0 877587092 2654208 294 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 648 294 249 194 0 34 0
[pid=4536] ppid=4509 vsize=37360 CPUtime=1.72
/proc/4536/stat : 4536 (aptsolutions.na) R 4509 4509 4159 34819 4229 4202496 8936 0 4 0 168 4 0 0 25 0 1 0 877587796 38256640 8829 1283457024 134512640 134971616 4294733440 18446744073709551615 134929102 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4536/statm: 9340 8829 209 113 0 8742 0
Current children cumulated CPU time (s) 6.8
Current children cumulated vsize (KiB) 39952

[startup+8.91015 s]
/proc/loadavg: 0.88 0.91 0.60 2/45 4536
/proc/meminfo: memFree=440864/1048576 swapFree=2084088/2097144
[pid=4509] ppid=4508 vsize=2592 CPUtime=5.08
/proc/4509/stat : 4509 (aptitude-trendy) S 4508 4509 4159 34819 4229 4202496 722 32326 0 232 0 0 487 21 18 0 1 0 877587092 2654208 294 1283457024 134512640 135304128 4286753296 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4509/statm: 648 294 249 194 0 34 0
[pid=4536] ppid=4509 vsize=42080 CPUtime=1.83
/proc/4536/stat : 4536 (aptsolutions.na) R 4509 4509 4159 34819 4229 4202496 10055 0 4 0 179 4 0 0 25 0 1 0 877587796 43089920 9948 1283457024 134512640 134971616 4294733440 18446744073709551615 134915911 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4536/statm: 10520 9948 209 113 0 9922 0
Current children cumulated CPU time (s) 6.91
Current children cumulated vsize (KiB) 44672

Child status: 0
Real time (s): 8.99739
CPU time (s): 7.01644
CPU user time (s): 6.75242
CPU system time (s): 0.264016
CPU usage (%): 77.9831
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.75242
system time used= 0.264016
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 44960
page faults= 236
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 317
involuntary context switches= 141

runsolver used 0 second user time and 0 second system time

The end