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/58a4a468-38a5-11df-a561-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/debian-dudf//58a4a468-38a5-11df-a561-00163e7a6f5e.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/58a4a468-38a5-11df-a561-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.89 1.13 1.16 5/46 22919
/proc/meminfo: memFree=745312/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2576 CPUtime=0
/proc/22918/stat : 22918 (aptitude-parano) R 22917 22918 2059 34821 2220 4202496 359 0 0 0 0 0 0 0 25 0 1 0 876076741 2637824 273 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/22918/statm: 644 273 232 194 0 30 0
[pid=22919] ppid=22918 vsize=2576 CPUtime=0
/proc/22919/stat : 22919 (aptitude-parano) R 22918 22918 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 1 0 876076741 2637824 41 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/22919/statm: 644 41 0 194 0 30 0

[startup+0.158535 s]
/proc/loadavg: 0.89 1.13 1.16 5/46 22919
/proc/meminfo: memFree=745312/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2592 CPUtime=0.04
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 570 1860 0 0 0 0 0 4 25 0 1 0 876076741 2654208 285 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 648 285 240 194 0 34 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2592

[startup+0.208552 s]
/proc/loadavg: 0.89 1.13 1.16 5/46 22919
/proc/meminfo: memFree=745312/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2592 CPUtime=0.04
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 570 1860 0 0 0 0 0 4 25 0 1 0 876076741 2654208 285 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 648 285 240 194 0 34 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2592

[startup+0.308577 s]
/proc/loadavg: 0.89 1.13 1.16 5/46 22919
/proc/meminfo: memFree=745312/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2592 CPUtime=0.04
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 570 1860 0 0 0 0 0 4 25 0 1 0 876076741 2654208 285 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 648 285 240 194 0 34 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2592

[startup+0.708693 s]
/proc/loadavg: 0.89 1.13 1.16 5/46 22919
/proc/meminfo: memFree=745312/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2592 CPUtime=0.04
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 570 1860 0 0 0 0 0 4 25 0 1 0 876076741 2654208 285 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 648 285 240 194 0 34 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2592

[startup+1.50893 s]
/proc/loadavg: 1.14 1.18 1.17 2/47 22929
/proc/meminfo: memFree=703208/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2592 CPUtime=0.04
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 570 1860 0 0 0 0 0 4 25 0 1 0 876076741 2654208 285 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 648 285 240 194 0 34 0
[pid=22929] ppid=22918 vsize=31024 CPUtime=1.45
/proc/22929/stat : 22929 (cudftodeb.nativ) R 22918 22918 2059 34821 2220 4202496 7329 0 0 0 143 2 0 0 25 0 1 0 876076746 31768576 7256 1283457024 134512640 135004320 4289398016 18446744073709551615 134949674 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/22929/statm: 7756 7256 225 121 0 7148 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 33616

[startup+3.10939 s]
/proc/loadavg: 1.14 1.18 1.17 2/47 22929
/proc/meminfo: memFree=682748/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2592 CPUtime=0.04
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 570 1860 0 0 0 0 0 4 25 0 1 0 876076741 2654208 285 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 648 285 240 194 0 34 0
[pid=22929] ppid=22918 vsize=59920 CPUtime=3.05
/proc/22929/stat : 22929 (cudftodeb.nativ) R 22918 22918 2059 34821 2220 4202496 14409 0 0 0 301 4 0 0 25 0 1 0 876076746 61358080 14336 1283457024 134512640 135004320 4289398016 18446744073709551615 134986387 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/22929/statm: 14980 14336 225 121 0 14372 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 62512

[startup+6.3103 s]
/proc/loadavg: 1.21 1.19 1.18 2/47 22929
/proc/meminfo: memFree=624716/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2592 CPUtime=0.04
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 570 1860 0 0 0 0 0 4 25 0 1 0 876076741 2654208 285 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 648 285 240 194 0 34 0
[pid=22929] ppid=22918 vsize=114968 CPUtime=6.25
/proc/22929/stat : 22929 (cudftodeb.nativ) R 22918 22918 2059 34821 2220 4202496 27969 0 0 0 616 9 0 0 25 0 1 0 876076746 117727232 27896 1283457024 134512640 135004320 4289398016 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/22929/statm: 28742 27896 237 121 0 28134 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 117560

[startup+12.7094 s]
/proc/loadavg: 1.19 1.19 1.18 1/47 22940
/proc/meminfo: memFree=627544/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2600 CPUtime=8.9
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 706 34330 0 1 0 0 862 28 19 0 1 0 876076741 2662400 296 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 650 296 249 194 0 36 0
[pid=22939] ppid=22918 vsize=46308 CPUtime=1.73
/proc/22939/stat : 22939 (aptitude) R 22918 22918 2059 34821 2220 4202496 15857 241 356 0 163 10 0 0 18 0 1 0 876077733 47419392 9267 1283457024 134512640 137933492 4293353008 18446744073709551615 4159076627 0 134217728 4096 0 0 0 0 17 0 0 0 0
/proc/22939/statm: 11577 9267 6807 836 0 2661 0
Current children cumulated CPU time (s) 10.63
Current children cumulated vsize (KiB) 48908

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

[startup+12.8095 s]
/proc/loadavg: 1.19 1.19 1.18 1/47 22940
/proc/meminfo: memFree=627544/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2600 CPUtime=8.9
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 706 34330 0 1 0 0 862 28 19 0 1 0 876076741 2662400 296 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 650 296 249 194 0 36 0
[pid=22939] ppid=22918 vsize=57100 CPUtime=1.83
/proc/22939/stat : 22939 (aptitude) R 22918 22918 2059 34821 2220 4202496 17111 241 356 0 173 10 0 0 18 0 2 0 876077733 58470400 10245 1283457024 134512640 137933492 4293353008 18446744073709551615 4153001244 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/22939/statm: 14275 10245 6896 836 0 5359 0
Current children cumulated CPU time (s) 10.73
Current children cumulated vsize (KiB) 59700

[startup+16.0103 s]
/proc/loadavg: 1.26 1.20 1.18 2/48 22943
/proc/meminfo: memFree=601620/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2600 CPUtime=13.76
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 731 59301 0 357 0 0 1334 42 18 0 1 0 876076741 2662400 296 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 650 296 249 194 0 36 0
Current children cumulated CPU time (s) 13.76
Current children cumulated vsize (KiB) 2600

[startup+19.211 s]
/proc/loadavg: 1.26 1.20 1.18 2/47 22945
/proc/meminfo: memFree=574968/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2600 CPUtime=13.76
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 731 59301 0 357 0 0 1334 42 18 0 1 0 876076741 2662400 296 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 650 296 249 194 0 36 0
[pid=22945] ppid=22918 vsize=65340 CPUtime=3.38
/proc/22945/stat : 22945 (aptsolutions.na) R 22918 22918 2059 34821 2220 4202496 15816 0 0 0 332 6 0 0 25 0 1 0 876078324 66908160 15695 1283457024 134512640 134971616 4292095840 18446744073709551615 134927612 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/22945/statm: 16335 15695 204 113 0 15737 0
Current children cumulated CPU time (s) 17.14
Current children cumulated vsize (KiB) 67940

[startup+20.0112 s]
/proc/loadavg: 1.26 1.20 1.18 2/47 22945
/proc/meminfo: memFree=555500/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2600 CPUtime=13.76
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 731 59301 0 357 0 0 1334 42 18 0 1 0 876076741 2662400 296 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 650 296 249 194 0 36 0
[pid=22945] ppid=22918 vsize=77492 CPUtime=4.17
/proc/22945/stat : 22945 (aptsolutions.na) R 22918 22918 2059 34821 2220 4202496 18794 0 0 0 408 9 0 0 25 0 1 0 876078324 79351808 18673 1283457024 134512640 134971616 4292095840 18446744073709551615 134946888 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/22945/statm: 19373 18673 204 113 0 18775 0
Current children cumulated CPU time (s) 17.93
Current children cumulated vsize (KiB) 80092

[startup+20.4114 s]
/proc/loadavg: 1.26 1.20 1.18 2/47 22945
/proc/meminfo: memFree=555500/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2600 CPUtime=13.76
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 731 59301 0 357 0 0 1334 42 18 0 1 0 876076741 2662400 296 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 650 296 249 194 0 36 0
[pid=22945] ppid=22918 vsize=89664 CPUtime=4.57
/proc/22945/stat : 22945 (aptsolutions.na) R 22918 22918 2059 34821 2220 4202496 21806 0 0 0 448 9 0 0 25 0 1 0 876078324 91815936 21685 1283457024 134512640 134971616 4292095840 18446744073709551615 4158604835 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/22945/statm: 22416 21685 209 113 0 21818 0
Current children cumulated CPU time (s) 18.33
Current children cumulated vsize (KiB) 92264

[startup+20.6114 s]
/proc/loadavg: 1.26 1.20 1.18 2/47 22945
/proc/meminfo: memFree=555500/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2600 CPUtime=13.76
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 731 59301 0 357 0 0 1334 42 18 0 1 0 876076741 2662400 296 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 650 296 249 194 0 36 0
[pid=22945] ppid=22918 vsize=99124 CPUtime=4.77
/proc/22945/stat : 22945 (aptsolutions.na) R 22918 22918 2059 34821 2220 4202496 23829 0 0 0 467 10 0 0 25 0 1 0 876078324 101502976 23708 1283457024 134512640 134971616 4292095840 18446744073709551615 134911543 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/22945/statm: 24781 23708 209 113 0 24183 0
Current children cumulated CPU time (s) 18.53
Current children cumulated vsize (KiB) 101724

[startup+20.7114 s]
/proc/loadavg: 1.26 1.20 1.18 2/47 22945
/proc/meminfo: memFree=555500/1048576 swapFree=2078744/2097144
[pid=22918] ppid=22917 vsize=2600 CPUtime=13.76
/proc/22918/stat : 22918 (aptitude-parano) S 22917 22918 2059 34821 2220 4202496 731 59301 0 357 0 0 1334 42 18 0 1 0 876076741 2662400 296 1283457024 134512640 135304128 4293060624 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/22918/statm: 650 296 249 194 0 36 0
[pid=22945] ppid=22918 vsize=108832 CPUtime=4.87
/proc/22945/stat : 22945 (aptsolutions.na) R 22918 22918 2059 34821 2220 4202496 25523 0 0 0 476 11 0 0 25 0 1 0 876078324 111443968 25402 1283457024 134512640 134971616 4292095840 18446744073709551615 4158604800 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/22945/statm: 27208 25402 209 113 0 26610 0
Current children cumulated CPU time (s) 18.63
Current children cumulated vsize (KiB) 111432

Child status: 0
Real time (s): 20.7395
CPU time (s): 18.6572
CPU user time (s): 18.1131
CPU system time (s): 0.544034
CPU usage (%): 89.9596
Max. virtual memory (cumulated for all children) (KiB): 118552

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 18.1131
system time used= 0.544034
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 85945
page faults= 357
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 204
involuntary context switches= 338

runsolver used 0.004 second user time and 0 second system time

The end