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/201012061533/aptitude-paranoid-1.0/218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/debian-dudf//218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-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: 1.30 1.06 1.04 5/46 7691
/proc/meminfo: memFree=762804/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2576 CPUtime=0
/proc/7690/stat : 7690 (aptitude-parano) R 7689 7690 2059 34821 2220 4202496 359 0 0 0 0 0 0 0 25 0 1 0 874947085 2637824 273 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/7690/statm: 644 273 232 194 0 30 0
[pid=7691] ppid=7690 vsize=2576 CPUtime=0
/proc/7691/stat : 7691 (aptitude-parano) R 7690 7690 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 1 0 874947085 2637824 41 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/7691/statm: 644 41 0 194 0 30 0

[startup+0.141553 s]
/proc/loadavg: 1.30 1.06 1.04 5/46 7691
/proc/meminfo: memFree=762804/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2592 CPUtime=0.05
/proc/7690/stat : 7690 (aptitude-parano) R 7689 7690 2059 34821 2220 4202496 552 1858 0 0 0 0 0 5 25 0 1 0 874947085 2654208 285 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/7690/statm: 648 285 240 194 0 34 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2592

[startup+0.211583 s]
/proc/loadavg: 1.30 1.06 1.04 5/46 7691
/proc/meminfo: memFree=762804/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2592 CPUtime=0.05
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 570 1858 0 0 0 0 0 5 25 0 1 0 874947085 2654208 285 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 648 285 240 194 0 34 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2592

[startup+0.311604 s]
/proc/loadavg: 1.30 1.06 1.04 5/46 7691
/proc/meminfo: memFree=762804/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2592 CPUtime=0.05
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 570 1858 0 0 0 0 0 5 25 0 1 0 874947085 2654208 285 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 648 285 240 194 0 34 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2592

[startup+0.711662 s]
/proc/loadavg: 1.30 1.06 1.04 5/46 7691
/proc/meminfo: memFree=762804/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2592 CPUtime=0.05
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 570 1858 0 0 0 0 0 5 25 0 1 0 874947085 2654208 285 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 648 285 240 194 0 34 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2592

[startup+1.51191 s]
/proc/loadavg: 1.27 1.06 1.04 2/47 7701
/proc/meminfo: memFree=720516/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2592 CPUtime=0.05
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 570 1858 0 0 0 0 0 5 25 0 1 0 874947085 2654208 285 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 648 285 240 194 0 34 0
[pid=7701] ppid=7690 vsize=30772 CPUtime=1.45
/proc/7701/stat : 7701 (cudftodeb.nativ) R 7690 7690 2059 34821 2220 4202496 7245 0 0 0 142 3 0 0 25 0 1 0 874947090 31510528 7172 1283457024 134512640 135004320 4293501168 18446744073709551615 134946674 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7701/statm: 7693 7172 225 121 0 7085 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 33364

[startup+3.10239 s]
/proc/loadavg: 1.27 1.06 1.04 2/47 7701
/proc/meminfo: memFree=700056/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2592 CPUtime=0.05
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 570 1858 0 0 0 0 0 5 25 0 1 0 874947085 2654208 285 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 648 285 240 194 0 34 0
[pid=7701] ppid=7690 vsize=59668 CPUtime=3.04
/proc/7701/stat : 7701 (cudftodeb.nativ) R 7690 7690 2059 34821 2220 4202496 14338 0 0 0 298 6 0 0 25 0 1 0 874947090 61100032 14265 1283457024 134512640 135004320 4293501168 18446744073709551615 134809856 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7701/statm: 14917 14265 225 121 0 14309 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 62260

[startup+6.30368 s]
/proc/loadavg: 1.27 1.06 1.04 2/47 7701
/proc/meminfo: memFree=643884/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2592 CPUtime=0.05
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 570 1858 0 0 0 0 0 5 25 0 1 0 874947085 2654208 285 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 648 285 240 194 0 34 0
[pid=7701] ppid=7690 vsize=114220 CPUtime=6.21
/proc/7701/stat : 7701 (cudftodeb.nativ) R 7690 7690 2059 34821 2220 4202496 27782 0 0 0 610 11 0 0 25 0 1 0 874947090 116961280 27709 1283457024 134512640 135004320 4293501168 18446744073709551615 4158830117 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7701/statm: 28555 27709 237 121 0 27947 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 116812

[startup+12.7148 s]
/proc/loadavg: 1.23 1.06 1.04 1/47 7712
/proc/meminfo: memFree=642760/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2600 CPUtime=9.03
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 706 33973 0 1 0 0 874 29 19 0 1 0 874947085 2662400 296 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 650 296 249 194 0 36 0
[pid=7711] ppid=7690 vsize=38576 CPUtime=1.38
/proc/7711/stat : 7711 (aptitude) R 7690 7690 2059 34821 2220 4202496 13697 240 363 0 128 10 0 0 18 0 1 0 874948095 39501824 7494 1283457024 134512640 137933492 4292193552 18446744073709551615 4160034320 0 134217728 4096 0 0 0 0 17 0 0 0 0
/proc/7711/statm: 9644 7494 6858 836 0 606 0
Current children cumulated CPU time (s) 10.41
Current children cumulated vsize (KiB) 41176

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

[startup+12.8149 s]
/proc/loadavg: 1.23 1.06 1.04 1/47 7712
/proc/meminfo: memFree=642760/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2600 CPUtime=9.03
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 706 33973 0 1 0 0 874 29 19 0 1 0 874947085 2662400 296 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 650 296 249 194 0 36 0
[pid=7711] ppid=7690 vsize=38708 CPUtime=1.48
/proc/7711/stat : 7711 (aptitude) R 7690 7690 2059 34821 2220 4202496 13784 240 363 0 137 11 0 0 18 0 1 0 874948095 39636992 7581 1283457024 134512640 137933492 4292193552 18446744073709551615 4153277261 0 134217728 4096 0 0 0 0 17 0 0 0 0
/proc/7711/statm: 9677 7581 6912 836 0 639 0
Current children cumulated CPU time (s) 10.51
Current children cumulated vsize (KiB) 41308

[startup+19.2064 s]
/proc/loadavg: 1.29 1.08 1.05 2/47 7717
/proc/meminfo: memFree=636436/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2600 CPUtime=16.08
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 731 64680 0 364 0 0 1558 50 18 0 1 0 874947085 2662400 296 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 650 296 249 194 0 36 0
[pid=7717] ppid=7690 vsize=18764 CPUtime=0.8
/proc/7717/stat : 7717 (aptsolutions.na) R 7690 7690 2059 34821 2220 4202496 4320 0 0 0 78 2 0 0 22 0 1 0 874948924 19214336 4205 1283457024 134512640 134971616 4289086592 18446744073709551615 134915911 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7717/statm: 4691 4205 204 113 0 4093 0
Current children cumulated CPU time (s) 16.88
Current children cumulated vsize (KiB) 21364

[startup+20.8068 s]
/proc/loadavg: 1.29 1.08 1.05 2/47 7717
/proc/meminfo: memFree=615852/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2600 CPUtime=16.08
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 731 64680 0 364 0 0 1558 50 18 0 1 0 874947085 2662400 296 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 650 296 249 194 0 36 0
[pid=7717] ppid=7690 vsize=49216 CPUtime=2.42
/proc/7717/stat : 7717 (aptsolutions.na) R 7690 7690 2059 34821 2220 4202496 11775 0 0 0 236 6 0 0 25 0 1 0 874948924 50397184 11660 1283457024 134512640 134971616 4289086592 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7717/statm: 12304 11660 204 113 0 11706 0
Current children cumulated CPU time (s) 18.5
Current children cumulated vsize (KiB) 51816

[startup+22.4071 s]
/proc/loadavg: 1.27 1.07 1.05 2/47 7717
/proc/meminfo: memFree=576048/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2600 CPUtime=16.08
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 731 64680 0 364 0 0 1558 50 18 0 1 0 874947085 2662400 296 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 650 296 249 194 0 36 0
[pid=7717] ppid=7690 vsize=75008 CPUtime=4.01
/proc/7717/stat : 7717 (aptsolutions.na) R 7690 7690 2059 34821 2220 4202496 18170 0 0 0 392 9 0 0 25 0 1 0 874948924 76808192 18055 1283457024 134512640 134971616 4289086592 18446744073709551615 134919349 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7717/statm: 18752 18055 204 113 0 18154 0
Current children cumulated CPU time (s) 20.09
Current children cumulated vsize (KiB) 77608

[startup+22.8072 s]
/proc/loadavg: 1.27 1.07 1.05 2/47 7717
/proc/meminfo: memFree=576048/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2600 CPUtime=16.08
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 731 64680 0 364 0 0 1558 50 18 0 1 0 874947085 2662400 296 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 650 296 249 194 0 36 0
[pid=7717] ppid=7690 vsize=83216 CPUtime=4.41
/proc/7717/stat : 7717 (aptsolutions.na) R 7690 7690 2059 34821 2220 4202496 20171 0 0 0 431 10 0 0 25 0 1 0 874948924 85213184 20056 1283457024 134512640 134971616 4289086592 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7717/statm: 20804 20056 208 113 0 20206 0
Current children cumulated CPU time (s) 20.49
Current children cumulated vsize (KiB) 85816

[startup+23.2072 s]
/proc/loadavg: 1.27 1.07 1.05 2/47 7717
/proc/meminfo: memFree=552116/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2600 CPUtime=16.08
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 731 64680 0 364 0 0 1558 50 18 0 1 0 874947085 2662400 296 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 650 296 249 194 0 36 0
[pid=7717] ppid=7690 vsize=98944 CPUtime=4.81
/proc/7717/stat : 7717 (aptsolutions.na) R 7690 7690 2059 34821 2220 4202496 23932 0 0 0 468 13 0 0 25 0 1 0 874948924 101318656 23817 1283457024 134512640 134971616 4289086592 18446744073709551615 134907871 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7717/statm: 24736 23817 209 113 0 24138 0
Current children cumulated CPU time (s) 20.89
Current children cumulated vsize (KiB) 101544

[startup+23.3073 s]
/proc/loadavg: 1.27 1.07 1.05 2/47 7717
/proc/meminfo: memFree=552116/1048576 swapFree=2078760/2097144
[pid=7690] ppid=7689 vsize=2600 CPUtime=16.08
/proc/7690/stat : 7690 (aptitude-parano) S 7689 7690 2059 34821 2220 4202496 731 64680 0 364 0 0 1558 50 18 0 1 0 874947085 2662400 296 1283457024 134512640 135304128 4291933952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7690/statm: 650 296 249 194 0 36 0
[pid=7717] ppid=7690 vsize=109836 CPUtime=4.91
/proc/7717/stat : 7717 (aptsolutions.na) R 7690 7690 2059 34821 2220 4202496 25705 0 0 0 478 13 0 0 25 0 1 0 874948924 112472064 25590 1283457024 134512640 134971616 4289086592 18446744073709551615 134908010 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7717/statm: 27459 25590 209 113 0 26861 0
Current children cumulated CPU time (s) 20.99
Current children cumulated vsize (KiB) 112436

Child status: 0
Real time (s): 23.335
CPU time (s): 21.0453
CPU user time (s): 20.4013
CPU system time (s): 0.64404
CPU usage (%): 90.1878
Max. virtual memory (cumulated for all children) (KiB): 116812

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 20.4013
system time used= 0.64404
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 91501
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= 230
involuntary context switches= 390

runsolver used 0 second user time and 0 second system time

The end