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/218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/debian-dudf//218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/218091ce-4bcc-11df-bc4e-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.88 0.94 0.98 4/41 9612
/proc/meminfo: memFree=660612/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2588 CPUtime=0.01
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 517 1360 0 0 0 0 0 1 25 0 1 0 878964194 2650112 281 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 647 281 237 194 0 33 0
[pid=9612] ppid=9604 vsize=2000 CPUtime=0.02
/proc/9612/stat : 9612 (cp) R 9604 9604 4159 34819 4229 4202496 253 0 0 0 0 2 0 0 25 0 1 0 878964195 2048000 182 1283457024 134512640 134614052 4291456832 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9612/statm: 500 182 145 25 0 46 0

[startup+0.212586 s]
/proc/loadavg: 0.88 0.94 0.98 4/41 9612
/proc/meminfo: memFree=660612/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2588 CPUtime=0.06
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 566 1859 0 0 0 0 0 6 25 0 1 0 878964194 2650112 284 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 2588

[startup+0.302615 s]
/proc/loadavg: 0.88 0.94 0.98 4/41 9612
/proc/meminfo: memFree=660612/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2588 CPUtime=0.06
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 566 1859 0 0 0 0 0 6 25 0 1 0 878964194 2650112 284 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 2588

[startup+0.412649 s]
/proc/loadavg: 0.88 0.94 0.98 4/41 9612
/proc/meminfo: memFree=660612/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2588 CPUtime=0.06
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 566 1859 0 0 0 0 0 6 25 0 1 0 878964194 2650112 284 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 2588

[startup+0.702714 s]
/proc/loadavg: 0.88 0.94 0.98 4/41 9612
/proc/meminfo: memFree=660612/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2588 CPUtime=0.06
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 566 1859 0 0 0 0 0 6 25 0 1 0 878964194 2650112 284 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 2588

[startup+1.50293 s]
/proc/loadavg: 0.88 0.94 0.98 2/42 9615
/proc/meminfo: memFree=627452/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2588 CPUtime=0.06
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 566 1859 0 0 0 0 0 6 25 0 1 0 878964194 2650112 284 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 647 284 240 194 0 33 0
[pid=9615] ppid=9604 vsize=30276 CPUtime=1.44
/proc/9615/stat : 9615 (cudftodeb.nativ) R 9604 9604 4159 34819 4229 4202496 7138 0 0 0 141 3 0 0 25 0 1 0 878964200 31002624 7065 1283457024 134512640 135004320 4293111952 18446744073709551615 134960236 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9615/statm: 7569 7065 225 121 0 6961 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 32864

[startup+3.10326 s]
/proc/loadavg: 0.88 0.94 0.98 2/42 9615
/proc/meminfo: memFree=607612/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2588 CPUtime=0.06
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 566 1859 0 0 0 0 0 6 25 0 1 0 878964194 2650112 284 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 647 284 240 194 0 33 0
[pid=9615] ppid=9604 vsize=58924 CPUtime=3.04
/proc/9615/stat : 9615 (cudftodeb.nativ) R 9604 9604 4159 34819 4229 4202496 14207 0 0 0 299 5 0 0 25 0 1 0 878964200 60338176 14134 1283457024 134512640 135004320 4293111952 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9615/statm: 14731 14134 225 121 0 14123 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 61512

[startup+6.30388 s]
/proc/loadavg: 0.89 0.94 0.98 2/42 9615
/proc/meminfo: memFree=551812/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2588 CPUtime=0.06
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 566 1859 0 0 0 0 0 6 25 0 1 0 878964194 2650112 284 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 647 284 240 194 0 33 0
[pid=9615] ppid=9604 vsize=113476 CPUtime=6.24
/proc/9615/stat : 9615 (cudftodeb.nativ) R 9604 9604 4159 34819 4229 4202496 27546 0 0 0 614 10 0 0 25 0 1 0 878964200 116199424 27473 1283457024 134512640 135004320 4293111952 18446744073709551615 134946704 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9615/statm: 28369 27473 237 121 0 27761 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 116064

[startup+12.7073 s]
/proc/loadavg: 0.89 0.94 0.98 1/42 9626
/proc/meminfo: memFree=552884/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2596 CPUtime=9.18
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 698 33968 0 1 0 0 886 32 18 0 1 0 878964194 2658304 295 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 649 295 249 194 0 35 0
[pid=9625] ppid=9604 vsize=108412 CPUtime=1.3
/proc/9625/stat : 9625 (aptitude) D 9604 9604 4159 34819 4229 4202496 7087 239 363 0 122 8 0 0 18 0 1 0 878965220 111013888 7288 1283457024 134512640 137933492 4293611136 18446744073709551615 4294960130 0 134217728 4096 0 18446744071564332537 0 0 17 0 0 0 0
/proc/9625/statm: 27103 7288 7194 836 0 65 0
Current children cumulated CPU time (s) 10.48
Current children cumulated vsize (KiB) 111008

[startup+25.5042 s]
/proc/loadavg: 0.99 0.96 0.98 2/42 9631
/proc/meminfo: memFree=459308/1048576 swapFree=2080288/2097144
[pid=9604] ppid=9603 vsize=2596 CPUtime=18.12
/proc/9604/stat : 9604 (aptitude-trendy) S 9603 9604 4159 34819 4229 4202496 723 66593 0 364 0 0 1760 52 18 0 1 0 878964194 2658304 295 1283457024 134512640 135304128 4292757456 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9604/statm: 649 295 249 194 0 35 0
[pid=9631] ppid=9604 vsize=104168 CPUtime=4.87
/proc/9631/stat : 9631 (aptsolutions.na) R 9604 9604 4159 34819 4229 4202496 24855 0 0 0 476 11 0 0 25 0 1 0 878966256 106668032 24744 1283457024 134512640 134971616 4293050448 18446744073709551615 134908010 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9631/statm: 26042 24744 209 113 0 25444 0
Current children cumulated CPU time (s) 22.99
Current children cumulated vsize (KiB) 106764

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

Child status: 0
Real time (s): 25.5869
CPU time (s): 23.0974
CPU user time (s): 22.4454
CPU system time (s): 0.65204
CPU usage (%): 90.2704
Max. virtual memory (cumulated for all children) (KiB): 116808

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 22.4454
system time used= 0.65204
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 93402
page faults= 364
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 210
involuntary context switches= 370

runsolver used 0 second user time and 0 second system time

The end