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/e0bd67a6-56d0-11df-b11f-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/debian-dudf//e0bd67a6-56d0-11df-b11f-00163e7a6f5e.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/e0bd67a6-56d0-11df-b11f-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: 1.04 1.08 1.02 1/40 3923
/proc/meminfo: memFree=677336/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=3024 CPUtime=0
/proc/3923/stat : 3923 (runsolver) D 3922 3923 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 885175966 3096576 93 1283457024 134512640 134586868 4287543792 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/3923/statm: 756 93 62 19 0 54 0

[startup+0.146316 s]
/proc/loadavg: 1.04 1.08 1.02 1/40 3923
/proc/meminfo: memFree=677336/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2584 CPUtime=0.02
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 566 1857 0 0 0 0 0 2 25 0 1 0 885175966 2646016 284 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.20836 s]
/proc/loadavg: 1.04 1.08 1.02 1/40 3923
/proc/meminfo: memFree=677336/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2584 CPUtime=0.02
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 566 1857 0 0 0 0 0 2 25 0 1 0 885175966 2646016 284 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.308387 s]
/proc/loadavg: 1.04 1.08 1.02 1/40 3923
/proc/meminfo: memFree=677336/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2584 CPUtime=0.02
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 566 1857 0 0 0 0 0 2 25 0 1 0 885175966 2646016 284 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.708465 s]
/proc/loadavg: 1.04 1.08 1.02 1/40 3923
/proc/meminfo: memFree=677336/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2584 CPUtime=0.02
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 566 1857 0 0 0 0 0 2 25 0 1 0 885175966 2646016 284 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+1.50868 s]
/proc/loadavg: 1.04 1.08 1.02 2/42 3934
/proc/meminfo: memFree=646608/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2584 CPUtime=0.02
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 566 1857 0 0 0 0 0 2 25 0 1 0 885175966 2646016 284 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 646 284 240 194 0 32 0
[pid=3934] ppid=3923 vsize=30456 CPUtime=1.43
/proc/3934/stat : 3934 (cudftodeb.nativ) R 3923 3923 4159 34819 4229 4202496 7143 0 8 0 142 1 0 0 25 0 1 0 885175969 31186944 7078 1283457024 134512640 135004320 4286884976 18446744073709551615 134959840 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/3934/statm: 7614 7078 225 121 0 7006 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 33040

[startup+3.10905 s]
/proc/loadavg: 1.04 1.08 1.02 2/42 3934
/proc/meminfo: memFree=622924/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2584 CPUtime=0.02
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 566 1857 0 0 0 0 0 2 25 0 1 0 885175966 2646016 284 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 646 284 240 194 0 32 0
[pid=3934] ppid=3923 vsize=28548 CPUtime=3.03
/proc/3934/stat : 3934 (cudftodeb.nativ) R 3923 3923 4159 34819 4229 4202496 11794 0 8 0 300 3 0 0 25 0 1 0 885175969 29233152 6666 1283457024 134512640 135004320 4286884976 18446744073709551615 4294960130 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/3934/statm: 7137 6666 237 121 0 6529 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 31132

[startup+6.30817 s]
/proc/loadavg: 1.12 1.09 1.02 2/42 3945
/proc/meminfo: memFree=615980/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2592 CPUtime=3.29
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 698 16963 0 9 0 0 321 8 16 0 1 0 885175966 2654208 295 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 648 295 249 194 0 34 0
[pid=3944] ppid=3923 vsize=47208 CPUtime=1.24
/proc/3944/stat : 3944 (aptitude) R 3923 3923 4159 34819 4229 4202496 9245 649 226 0 114 10 0 0 20 0 2 0 885176368 48340992 6080 1283457024 134512640 137933492 4290470752 18446744073709551615 4153157960 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/3944/statm: 11802 6080 3713 836 0 6467 0
Current children cumulated CPU time (s) 4.53
Current children cumulated vsize (KiB) 49800
heavy processes:

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

[startup+6.4082 s]
/proc/loadavg: 1.12 1.09 1.02 2/43 3948
/proc/meminfo: memFree=610088/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2592 CPUtime=3.29
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 698 16963 0 9 0 0 321 8 16 0 1 0 885175966 2654208 295 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 648 295 249 194 0 34 0
[pid=3944] ppid=3923 vsize=47208 CPUtime=1.34
/proc/3944/stat : 3944 (aptitude) R 3923 3923 4159 34819 4229 4202496 9246 649 226 0 124 10 0 0 20 0 2 0 885176368 48340992 6080 1283457024 134512640 137933492 4290470752 18446744073709551615 4154703313 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/3944/statm: 11802 6080 3713 836 0 6467 0
[pid=3944/tid=3946] ppid=3923 vsize=47208 CPUtime=0
/proc/3944/task/3946/stat : 3946 (aptitude) S 3923 3923 4159 34819 4229 4202560 5 649 0 0 0 0 0 0 15 0 2 0 885176536 48340992 6080 1283457024 134512640 137933492 4290470752 18446744073709551615 4294960130 0 134217728 4096 0 18446612133359098816 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.63
Current children cumulated vsize (KiB) 49800

[startup+8.00476 s]
/proc/loadavg: 1.12 1.09 1.02 2/42 3950
/proc/meminfo: memFree=608012/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2592 CPUtime=5.3
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 723 29982 0 237 0 0 512 18 18 0 1 0 885175966 2654208 295 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 648 295 249 194 0 34 0
[pid=3950] ppid=3923 vsize=19752 CPUtime=0.84
/proc/3950/stat : 3950 (aptsolutions.na) R 3923 3923 4159 34819 4229 4202496 4536 0 9 0 82 2 0 0 20 0 1 0 885176678 20226048 4434 1283457024 134512640 134971616 4287477440 18446744073709551615 134801564 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/3950/statm: 4938 4434 204 113 0 4340 0
Current children cumulated CPU time (s) 6.14
Current children cumulated vsize (KiB) 22344

[startup+8.80494 s]
/proc/loadavg: 1.11 1.09 1.02 2/42 3950
/proc/meminfo: memFree=586808/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2592 CPUtime=5.3
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 723 29982 0 237 0 0 512 18 18 0 1 0 885175966 2654208 295 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 648 295 249 194 0 34 0
[pid=3950] ppid=3923 vsize=35128 CPUtime=1.64
/proc/3950/stat : 3950 (aptsolutions.na) R 3923 3923 4159 34819 4229 4202496 8364 0 9 0 158 6 0 0 23 0 1 0 885176678 35971072 8262 1283457024 134512640 134971616 4287477440 18446744073709551615 134945264 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/3950/statm: 8782 8262 204 113 0 8184 0
Current children cumulated CPU time (s) 6.94
Current children cumulated vsize (KiB) 37720

[startup+9.005 s]
/proc/loadavg: 1.11 1.09 1.02 2/42 3950
/proc/meminfo: memFree=586808/1048576 swapFree=2080268/2097144
[pid=3923] ppid=3922 vsize=2592 CPUtime=5.3
/proc/3923/stat : 3923 (aptitude-trendy) S 3922 3923 4159 34819 4229 4202496 723 29982 0 237 0 0 512 18 18 0 1 0 885175966 2654208 295 1283457024 134512640 135304128 4292802512 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/3923/statm: 648 295 249 194 0 34 0
[pid=3950] ppid=3923 vsize=46484 CPUtime=1.84
/proc/3950/stat : 3950 (aptsolutions.na) R 3923 3923 4159 34819 4229 4202496 10875 0 9 0 178 6 0 0 24 0 1 0 885176678 47599616 10773 1283457024 134512640 134971616 4287477440 18446744073709551615 4158727715 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/3950/statm: 11621 10773 209 113 0 11023 0
Current children cumulated CPU time (s) 7.14
Current children cumulated vsize (KiB) 49076

Child status: 0
Real time (s): 9.03942
CPU time (s): 7.18445
CPU user time (s): 6.93643
CPU system time (s): 0.248015
CPU usage (%): 79.4791
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.93643
system time used= 0.248015
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 42476
page faults= 246
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 324
involuntary context switches= 136

runsolver used 0 second user time and 0.004 second system time

The end