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/eeee44ce-5407-11df-b11f-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/debian-dudf//eeee44ce-5407-11df-b11f-00163e7a6f5e.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/eeee44ce-5407-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.46 1.35 1.27 4/46 1680
/proc/meminfo: memFree=747044/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2584 CPUtime=0.02
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 568 1857 0 0 0 0 0 2 25 0 1 0 876709851 2646016 283 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 646 283 240 194 0 32 0
[pid=1680] ppid=1670 vsize=3024 CPUtime=0.01
/proc/1680/stat : 1680 (cudftodeb.nativ) R 1670 1670 2059 34821 2220 4202496 474 0 0 0 0 1 0 0 25 0 1 0 876709854 3096576 401 1283457024 134512640 135004320 4287517504 18446744073709551615 134986210 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1680/statm: 756 401 224 121 0 148 0

[startup+0.182167 s]
/proc/loadavg: 1.46 1.35 1.27 4/46 1680
/proc/meminfo: memFree=747044/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2584 CPUtime=0.02
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 568 1857 0 0 0 0 0 2 25 0 1 0 876709851 2646016 283 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 646 283 240 194 0 32 0
[pid=1680] ppid=1670 vsize=5752 CPUtime=0.15
/proc/1680/stat : 1680 (cudftodeb.nativ) R 1670 1670 2059 34821 2220 4202496 1148 0 0 0 14 1 0 0 25 0 1 0 876709854 5890048 1075 1283457024 134512640 135004320 4287517504 18446744073709551615 134946654 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1680/statm: 1438 1075 225 121 0 830 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 8336

[startup+0.212172 s]
/proc/loadavg: 1.46 1.35 1.27 4/46 1680
/proc/meminfo: memFree=747044/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2584 CPUtime=0.02
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 568 1857 0 0 0 0 0 2 25 0 1 0 876709851 2646016 283 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 646 283 240 194 0 32 0
[pid=1680] ppid=1670 vsize=6496 CPUtime=0.19
/proc/1680/stat : 1680 (cudftodeb.nativ) R 1670 1670 2059 34821 2220 4202496 1306 0 0 0 18 1 0 0 25 0 1 0 876709854 6651904 1233 1283457024 134512640 135004320 4287517504 18446744073709551615 134828407 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1680/statm: 1624 1233 225 121 0 1016 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 9080

[startup+0.312207 s]
/proc/loadavg: 1.46 1.35 1.27 4/46 1680
/proc/meminfo: memFree=747044/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2584 CPUtime=0.02
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 568 1857 0 0 0 0 0 2 25 0 1 0 876709851 2646016 283 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 646 283 240 194 0 32 0
[pid=1680] ppid=1670 vsize=8480 CPUtime=0.29
/proc/1680/stat : 1680 (cudftodeb.nativ) R 1670 1670 2059 34821 2220 4202496 1771 0 0 0 28 1 0 0 25 0 1 0 876709854 8683520 1698 1283457024 134512640 135004320 4287517504 18446744073709551615 134950940 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1680/statm: 2120 1698 225 121 0 1512 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 11064

[startup+0.712285 s]
/proc/loadavg: 1.46 1.35 1.27 4/46 1680
/proc/meminfo: memFree=747044/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2584 CPUtime=0.02
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 568 1857 0 0 0 0 0 2 25 0 1 0 876709851 2646016 283 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 646 283 240 194 0 32 0
[pid=1680] ppid=1670 vsize=16576 CPUtime=0.69
/proc/1680/stat : 1680 (cudftodeb.nativ) R 1670 1670 2059 34821 2220 4202496 3759 0 0 0 66 3 0 0 25 0 1 0 876709854 16973824 3686 1283457024 134512640 135004320 4287517504 18446744073709551615 134948148 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1680/statm: 4144 3686 225 121 0 3536 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 19160

[startup+1.51245 s]
/proc/loadavg: 1.46 1.35 1.27 2/47 1681
/proc/meminfo: memFree=726452/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2584 CPUtime=0.02
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 568 1857 0 0 0 0 0 2 25 0 1 0 876709851 2646016 283 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 646 283 240 194 0 32 0
[pid=1680] ppid=1670 vsize=31456 CPUtime=1.48
/proc/1680/stat : 1680 (cudftodeb.nativ) R 1670 1670 2059 34821 2220 4202496 7403 0 0 0 143 5 0 0 25 0 1 0 876709854 32210944 7330 1283457024 134512640 135004320 4287517504 18446744073709551615 134625384 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1680/statm: 7864 7330 225 121 0 7256 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 34040

[startup+3.11283 s]
/proc/loadavg: 1.46 1.35 1.27 2/47 1681
/proc/meminfo: memFree=702520/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2584 CPUtime=0.02
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 568 1857 0 0 0 0 0 2 25 0 1 0 876709851 2646016 283 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 646 283 240 194 0 32 0
[pid=1680] ppid=1670 vsize=60504 CPUtime=3.08
/proc/1680/stat : 1680 (cudftodeb.nativ) R 1670 1670 2059 34821 2220 4202496 14628 0 0 0 299 9 0 0 25 0 1 0 876709854 61956096 14555 1283457024 134512640 135004320 4287517504 18446744073709551615 134856256 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1680/statm: 15126 14555 237 121 0 14518 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 63088

[startup+6.30228 s]
/proc/loadavg: 1.42 1.34 1.27 3/48 1693
/proc/meminfo: memFree=699412/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2592 CPUtime=3.34
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 699 19656 0 1 0 0 316 18 18 0 1 0 876709851 2654208 294 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 648 294 249 194 0 34 0
[pid=1691] ppid=1670 vsize=49044 CPUtime=1.61
/proc/1691/stat : 1691 (aptitude) R 1670 1670 2059 34821 2220 4202496 10475 652 153 0 148 13 0 0 21 0 2 0 876710262 50221056 6656 1283457024 134512640 137933492 4291970272 18446744073709551615 135855000 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/1691/statm: 12261 6656 3848 836 0 6883 0
[pid=1691/tid=1693] ppid=1670 vsize=49044 CPUtime=0.12
/proc/1691/task/1693/stat : 1693 (aptitude) S 1670 1670 2059 34821 2220 4202560 701 652 0 0 12 0 0 0 16 0 2 0 876710395 50221056 6656 1283457024 134512640 137933492 4291970272 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680194816 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.95
Current children cumulated vsize (KiB) 51636
heavy processes:

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

[startup+6.4123 s]
/proc/loadavg: 1.42 1.34 1.27 2/48 1695
/proc/meminfo: memFree=696808/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2592 CPUtime=3.34
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 699 19656 0 1 0 0 316 18 18 0 1 0 876709851 2654208 294 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 648 294 249 194 0 34 0
[pid=1691] ppid=1670 vsize=49044 CPUtime=1.72
/proc/1691/stat : 1691 (aptitude) R 1670 1670 2059 34821 2220 4202496 11465 1062 153 0 158 14 0 0 23 0 2 0 876710262 50221056 6659 1283457024 134512640 137933492 4291970272 18446744073709551615 4159836572 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/1691/statm: 12261 6659 3851 836 0 6883 0
[pid=1691/tid=1693] ppid=1670 vsize=49044 CPUtime=0.12
/proc/1691/task/1693/stat : 1693 (aptitude) S 1670 1670 2059 34821 2220 4202560 701 1062 0 0 12 0 0 0 16 0 2 0 876710395 50221056 6659 1283457024 134512640 137933492 4291970272 18446744073709551615 4294960130 0 134217728 4096 0 18446612132680194816 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 5.06
Current children cumulated vsize (KiB) 51636

[startup+7.21244 s]
/proc/loadavg: 1.42 1.34 1.27 2/47 1697
/proc/meminfo: memFree=704752/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2592 CPUtime=5.12
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 725 32323 0 154 0 0 478 34 18 0 1 0 876709851 2654208 294 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 648 294 249 194 0 34 0
[pid=1697] ppid=1670 vsize=17516 CPUtime=0.74
/proc/1697/stat : 1697 (aptsolutions.na) R 1670 1670 2059 34821 2220 4202496 4015 0 0 0 72 2 0 0 22 0 1 0 876710498 17936384 3901 1283457024 134512640 134971616 4294259056 18446744073709551615 134918896 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1697/statm: 4379 3901 204 113 0 3781 0
Current children cumulated CPU time (s) 5.86
Current children cumulated vsize (KiB) 20108

[startup+8.01259 s]
/proc/loadavg: 1.42 1.34 1.27 2/47 1697
/proc/meminfo: memFree=683672/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2592 CPUtime=5.12
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 725 32323 0 154 0 0 478 34 18 0 1 0 876709851 2654208 294 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 648 294 249 194 0 34 0
[pid=1697] ppid=1670 vsize=32892 CPUtime=1.54
/proc/1697/stat : 1697 (aptsolutions.na) R 1670 1670 2059 34821 2220 4202496 7801 0 0 0 151 3 0 0 25 0 1 0 876710498 33681408 7687 1283457024 134512640 134971616 4294259056 18446744073709551615 134920351 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1697/statm: 8223 7687 204 113 0 7625 0
Current children cumulated CPU time (s) 6.66
Current children cumulated vsize (KiB) 35484

[startup+8.21262 s]
/proc/loadavg: 1.42 1.34 1.27 2/47 1697
/proc/meminfo: memFree=683672/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2592 CPUtime=5.12
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 725 32323 0 154 0 0 478 34 18 0 1 0 876709851 2654208 294 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 648 294 249 194 0 34 0
[pid=1697] ppid=1670 vsize=38360 CPUtime=1.74
/proc/1697/stat : 1697 (aptsolutions.na) R 1670 1670 2059 34821 2220 4202496 9199 0 0 0 170 4 0 0 25 0 1 0 876710498 39280640 9085 1283457024 134512640 134971616 4294259056 18446744073709551615 134915776 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1697/statm: 9590 9085 209 113 0 8992 0
Current children cumulated CPU time (s) 6.86
Current children cumulated vsize (KiB) 40952

[startup+8.31265 s]
/proc/loadavg: 1.42 1.34 1.27 2/47 1697
/proc/meminfo: memFree=683672/1048576 swapFree=2078696/2097144
[pid=1670] ppid=1669 vsize=2592 CPUtime=5.12
/proc/1670/stat : 1670 (aptitude-parano) S 1669 1670 2059 34821 2220 4202496 725 32323 0 154 0 0 478 34 18 0 1 0 876709851 2654208 294 1283457024 134512640 135304128 4294709664 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/1670/statm: 648 294 249 194 0 34 0
[pid=1697] ppid=1670 vsize=42824 CPUtime=1.84
/proc/1697/stat : 1697 (aptsolutions.na) R 1670 1670 2059 34821 2220 4202496 10251 0 0 0 179 5 0 0 25 0 1 0 876710498 43851776 10137 1283457024 134512640 134971616 4294259056 18446744073709551615 4159313487 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/1697/statm: 10706 10137 209 113 0 10108 0
Current children cumulated CPU time (s) 6.96
Current children cumulated vsize (KiB) 45416

Child status: 0
Real time (s): 8.38583
CPU time (s): 7.05644
CPU user time (s): 6.64842
CPU system time (s): 0.408025
CPU usage (%): 84.1472
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.64841
system time used= 0.408025
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 44975
page faults= 154
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 140
involuntary context switches= 144

runsolver used 0 second user time and 0 second system time

The end