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/rand915.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny/rand915.sarge-etch-lenny.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand915.sarge-etch-lenny.cudf.sarge-etch-lenny.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.38 1.28 1.20 1/46 24429
/proc/meminfo: memFree=764108/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2576 CPUtime=0
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 398 156 0 0 0 0 0 0 25 0 1 0 876162851 2637824 276 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 644 276 235 194 0 30 0
[pid=24429] ppid=24427 vsize=1756 CPUtime=0
/proc/24429/stat : 24429 (mkdir) D 24427 24427 2059 34821 2220 4194304 199 0 0 0 0 0 0 0 25 0 1 0 876162851 1798144 131 1283457024 134512640 134551716 4291778464 18446744073709551615 4294960130 0 0 0 0 18446744071564252162 0 0 17 0 0 0 0
/proc/24429/statm: 439 131 111 10 0 44 0

[startup+0.141646 s]
/proc/loadavg: 1.38 1.28 1.20 1/46 24429
/proc/meminfo: memFree=764108/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2588 CPUtime=0.02
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 569 1860 0 0 0 0 0 2 25 0 1 0 876162851 2650112 284 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.211668 s]
/proc/loadavg: 1.38 1.28 1.20 1/46 24429
/proc/meminfo: memFree=764108/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2588 CPUtime=0.02
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 569 1860 0 0 0 0 0 2 25 0 1 0 876162851 2650112 284 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.311697 s]
/proc/loadavg: 1.38 1.28 1.20 1/46 24429
/proc/meminfo: memFree=764108/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2588 CPUtime=0.02
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 569 1860 0 0 0 0 0 2 25 0 1 0 876162851 2650112 284 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.7118 s]
/proc/loadavg: 1.38 1.28 1.20 1/46 24429
/proc/meminfo: memFree=764108/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2588 CPUtime=0.02
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 569 1860 0 0 0 0 0 2 25 0 1 0 876162851 2650112 284 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+1.512 s]
/proc/loadavg: 1.38 1.28 1.20 2/47 24438
/proc/meminfo: memFree=729660/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2588 CPUtime=0.02
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 569 1860 0 0 0 0 0 2 25 0 1 0 876162851 2650112 284 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 647 284 240 194 0 33 0
[pid=24438] ppid=24427 vsize=32444 CPUtime=1.46
/proc/24438/stat : 24438 (cudftodeb.nativ) R 24427 24427 2059 34821 2220 4202496 7673 0 0 0 145 1 0 0 25 0 1 0 876162856 33222656 7600 1283457024 134512640 135004320 4293953888 18446744073709551615 134948016 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/24438/statm: 8111 7600 225 121 0 7503 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 35032

[startup+3.11233 s]
/proc/loadavg: 1.38 1.28 1.20 2/47 24438
/proc/meminfo: memFree=708084/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2588 CPUtime=0.02
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 569 1860 0 0 0 0 0 2 25 0 1 0 876162851 2650112 284 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 647 284 240 194 0 33 0
[pid=24438] ppid=24427 vsize=67624 CPUtime=3.07
/proc/24438/stat : 24438 (cudftodeb.nativ) R 24427 24427 2059 34821 2220 4202496 16321 0 0 0 304 3 0 0 25 0 1 0 876162856 69246976 16246 1283457024 134512640 135004320 4293953888 18446744073709551615 134943783 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/24438/statm: 16906 16246 237 121 0 16298 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 70212

[startup+6.30802 s]
/proc/loadavg: 1.35 1.28 1.20 2/49 24446
/proc/meminfo: memFree=718344/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2596 CPUtime=5.42
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 652 24441 0 0 0 0 528 14 22 0 1 0 876162851 2658304 287 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 649 287 241 194 0 35 0
[pid=24442] ppid=24427 vsize=101504 CPUtime=0.19
/proc/24442/stat : 24442 (apt-get) D 24427 24427 2059 34821 2220 4202496 551 1676 1 0 0 0 17 2 24 0 1 0 876163398 103940096 422 1283457024 134512640 134619611 4293047984 18446744073709551615 4294960130 0 0 4096 134217728 18446744071696460772 0 0 17 0 0 0 0
/proc/24442/statm: 25376 422 374 27 0 70 0
Current children cumulated CPU time (s) 5.61
Current children cumulated vsize (KiB) 104100

[startup+12.7064 s]
/proc/loadavg: 1.32 1.27 1.20 3/48 24452
/proc/meminfo: memFree=654272/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2596 CPUtime=5.65
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 701 26840 0 1 0 0 548 17 18 0 1 0 876162851 2658304 295 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 649 295 249 194 0 35 0
[pid=24448] ppid=24427 vsize=74368 CPUtime=5.34
/proc/24448/stat : 24448 (aptitude) S 24427 24427 2059 34821 2220 4202496 18956 651 265 0 522 12 0 0 23 0 2 0 876163493 76152832 12857 1283457024 134512640 137933492 4288972944 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/24448/statm: 18592 12857 5659 836 0 11274 0
[pid=24448/tid=24450] ppid=24427 vsize=74368 CPUtime=2.68
/proc/24448/task/24450/stat : 24450 (aptitude) R 24427 24427 2059 34821 2220 4202560 5039 651 0 0 266 2 0 0 19 0 2 0 876163705 76152832 12857 1283457024 134512640 137933492 4288972944 18446744073709551615 136299474 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.99
Current children cumulated vsize (KiB) 76964

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

[startup+12.8064 s]
/proc/loadavg: 1.32 1.27 1.20 3/48 24452
/proc/meminfo: memFree=654272/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2596 CPUtime=5.65
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 701 26840 0 1 0 0 548 17 18 0 1 0 876162851 2658304 295 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 649 295 249 194 0 35 0
[pid=24448] ppid=24427 vsize=74764 CPUtime=5.44
/proc/24448/stat : 24448 (aptitude) S 24427 24427 2059 34821 2220 4202496 19034 651 265 0 532 12 0 0 20 0 2 0 876163493 76558336 12935 1283457024 134512640 137933492 4288972944 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/24448/statm: 18691 12935 5660 836 0 11373 0
[pid=24448/tid=24450] ppid=24427 vsize=74764 CPUtime=2.78
/proc/24448/task/24450/stat : 24450 (aptitude) R 24427 24427 2059 34821 2220 4202560 5116 651 0 0 276 2 0 0 19 0 2 0 876163705 76558336 12935 1283457024 134512640 137933492 4288972944 18446744073709551615 136463248 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.09
Current children cumulated vsize (KiB) 77360

[startup+16.0072 s]
/proc/loadavg: 1.30 1.27 1.20 2/48 24452
/proc/meminfo: memFree=641004/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2596 CPUtime=5.65
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 701 26840 0 1 0 0 548 17 18 0 1 0 876162851 2658304 295 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 649 295 249 194 0 35 0
[pid=24448] ppid=24427 vsize=88988 CPUtime=8.64
/proc/24448/stat : 24448 (aptitude) S 24427 24427 2059 34821 2220 4202496 22360 651 265 0 852 12 0 0 15 0 2 0 876163493 91123712 16261 1283457024 134512640 137933492 4288972944 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/24448/statm: 22247 16261 5660 836 0 14929 0
[pid=24448/tid=24450] ppid=24427 vsize=88988 CPUtime=5.98
/proc/24448/task/24450/stat : 24450 (aptitude) R 24427 24427 2059 34821 2220 4202560 8441 651 0 0 596 2 0 0 25 0 2 0 876163705 91123712 16261 1283457024 134512640 137933492 4288972944 18446744073709551615 136328774 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 14.29
Current children cumulated vsize (KiB) 91584

[startup+19.209 s]
/proc/loadavg: 1.30 1.27 1.20 2/47 24454
/proc/meminfo: memFree=674988/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2596 CPUtime=16.73
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 727 53465 0 266 0 0 1637 36 18 0 1 0 876162851 2658304 295 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 649 295 249 194 0 35 0
[pid=24454] ppid=24427 vsize=19004 CPUtime=0.78
/proc/24454/stat : 24454 (aptsolutions.na) R 24427 24427 2059 34821 2220 4202496 4367 0 0 0 75 3 0 0 21 0 1 0 876164693 19460096 4253 1283457024 134512640 134971616 4286790240 18446744073709551615 134799538 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/24454/statm: 4751 4253 204 113 0 4153 0
Current children cumulated CPU time (s) 17.51
Current children cumulated vsize (KiB) 21600

[startup+20.0092 s]
/proc/loadavg: 1.27 1.26 1.20 2/47 24454
/proc/meminfo: memFree=652916/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2596 CPUtime=16.73
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 727 53465 0 266 0 0 1637 36 18 0 1 0 876162851 2658304 295 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 649 295 249 194 0 35 0
[pid=24454] ppid=24427 vsize=34824 CPUtime=1.58
/proc/24454/stat : 24454 (aptsolutions.na) R 24427 24427 2059 34821 2220 4202496 8269 0 0 0 154 4 0 0 23 0 1 0 876164693 35659776 8153 1283457024 134512640 134971616 4286790240 18446744073709551615 134760775 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/24454/statm: 8706 8153 204 113 0 8108 0
Current children cumulated CPU time (s) 18.31
Current children cumulated vsize (KiB) 37420

[startup+20.4093 s]
/proc/loadavg: 1.27 1.26 1.20 2/47 24454
/proc/meminfo: memFree=652916/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2596 CPUtime=16.73
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 727 53465 0 266 0 0 1637 36 18 0 1 0 876162851 2658304 295 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 649 295 249 194 0 35 0
[pid=24454] ppid=24427 vsize=42016 CPUtime=1.98
/proc/24454/stat : 24454 (aptsolutions.na) R 24427 24427 2059 34821 2220 4202496 10078 0 0 0 194 4 0 0 25 0 1 0 876164693 43024384 9962 1283457024 134512640 134971616 4286790240 18446744073709551615 134919130 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/24454/statm: 10504 9962 204 113 0 9906 0
Current children cumulated CPU time (s) 18.71
Current children cumulated vsize (KiB) 44612

[startup+20.8094 s]
/proc/loadavg: 1.27 1.26 1.20 2/47 24454
/proc/meminfo: memFree=652916/1048576 swapFree=2078744/2097144
[pid=24427] ppid=24426 vsize=2596 CPUtime=16.73
/proc/24427/stat : 24427 (aptitude-parano) S 24426 24427 2059 34821 2220 4202496 727 53465 0 266 0 0 1637 36 18 0 1 0 876162851 2658304 295 1283457024 134512640 135304128 4287584992 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/24427/statm: 649 295 249 194 0 35 0
[pid=24454] ppid=24427 vsize=53472 CPUtime=2.37
/proc/24454/stat : 24454 (aptsolutions.na) R 24427 24427 2059 34821 2220 4202496 12842 0 0 0 231 6 0 0 25 0 1 0 876164693 54755328 12726 1283457024 134512640 134971616 4286790240 18446744073709551615 4294960130 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/24454/statm: 13368 12726 209 113 0 12770 0
Current children cumulated CPU time (s) 19.1
Current children cumulated vsize (KiB) 56068

Child status: 0
Real time (s): 20.8152
CPU time (s): 19.1212
CPU user time (s): 18.6932
CPU system time (s): 0.428026
CPU usage (%): 91.8618
Max. virtual memory (cumulated for all children) (KiB): 111008

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 18.6932
system time used= 0.428026
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67052
page faults= 266
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 307
involuntary context switches= 449

runsolver used 0.012 second user time and 0 second system time

The end