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/rand753.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand753.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand753.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.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.04 1.13 1.10 6/46 19144
/proc/meminfo: memFree=738316/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2588 CPUtime=0
/proc/19137/stat : 19137 (aptitude-parano) R 19136 19137 2059 34821 2220 4202496 480 1158 0 0 0 0 0 0 25 0 1 0 875908705 2650112 281 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/19137/statm: 647 281 237 194 0 33 0
[pid=19144] ppid=19137 vsize=2588 CPUtime=0
/proc/19144/stat : 19144 (aptitude-parano) R 19137 19137 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 1 0 875908705 2650112 44 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/19144/statm: 647 44 0 194 0 33 0

[startup+0.217213 s]
/proc/loadavg: 1.04 1.13 1.10 6/46 19144
/proc/meminfo: memFree=738316/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2588 CPUtime=0.04
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 569 1859 0 0 0 0 0 4 25 0 1 0 875908705 2650112 284 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2588

[startup+0.307236 s]
/proc/loadavg: 1.04 1.13 1.10 6/46 19144
/proc/meminfo: memFree=738316/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2588 CPUtime=0.04
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 569 1859 0 0 0 0 0 4 25 0 1 0 875908705 2650112 284 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2588

[startup+0.407268 s]
/proc/loadavg: 1.04 1.13 1.10 6/46 19144
/proc/meminfo: memFree=738316/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2588 CPUtime=0.04
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 569 1859 0 0 0 0 0 4 25 0 1 0 875908705 2650112 284 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2588

[startup+0.707347 s]
/proc/loadavg: 1.04 1.13 1.10 6/46 19144
/proc/meminfo: memFree=738316/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2588 CPUtime=0.04
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 569 1859 0 0 0 0 0 4 25 0 1 0 875908705 2650112 284 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2588

[startup+1.50752 s]
/proc/loadavg: 1.04 1.12 1.10 2/47 19148
/proc/meminfo: memFree=695848/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2588 CPUtime=0.04
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 569 1859 0 0 0 0 0 4 25 0 1 0 875908705 2650112 284 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 647 284 240 194 0 33 0
[pid=19148] ppid=19137 vsize=32020 CPUtime=1.45
/proc/19148/stat : 19148 (cudftodeb.nativ) R 19137 19137 2059 34821 2220 4202496 7575 0 0 0 142 3 0 0 25 0 1 0 875908710 32788480 7502 1283457024 134512640 135004320 4288254960 18446744073709551615 134945048 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19148/statm: 8005 7502 225 121 0 7397 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 34608

[startup+3.10802 s]
/proc/loadavg: 1.04 1.12 1.10 2/47 19148
/proc/meminfo: memFree=674768/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2588 CPUtime=0.04
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 569 1859 0 0 0 0 0 4 25 0 1 0 875908705 2650112 284 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 647 284 240 194 0 33 0
[pid=19148] ppid=19137 vsize=62412 CPUtime=3.04
/proc/19148/stat : 19148 (cudftodeb.nativ) R 19137 19137 2059 34821 2220 4202496 15012 0 0 0 299 5 0 0 25 0 1 0 875908710 63909888 14939 1283457024 134512640 135004320 4288254960 18446744073709551615 134948034 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19148/statm: 15603 14939 225 121 0 14995 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 65000

[startup+6.30898 s]
/proc/loadavg: 1.04 1.12 1.10 2/47 19148
/proc/meminfo: memFree=612520/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2588 CPUtime=0.04
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 569 1859 0 0 0 0 0 4 25 0 1 0 875908705 2650112 284 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 647 284 240 194 0 33 0
[pid=19148] ppid=19137 vsize=115468 CPUtime=6.23
/proc/19148/stat : 19148 (cudftodeb.nativ) R 19137 19137 2059 34821 2220 4202496 28074 0 0 0 608 15 0 0 25 0 1 0 875908710 118239232 28001 1283457024 134512640 135004320 4288254960 18446744073709551615 4158408271 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19148/statm: 28867 28001 237 121 0 28259 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 118056

[startup+12.7064 s]
/proc/loadavg: 1.03 1.12 1.10 1/47 19159
/proc/meminfo: memFree=614680/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=8.88
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 703 34598 0 1 0 0 856 32 19 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19158] ppid=19137 vsize=108412 CPUtime=1.38
/proc/19158/stat : 19158 (aptitude) D 19137 19137 2059 34821 2220 4202496 7510 240 388 0 128 10 0 0 18 0 1 0 875909710 111013888 7737 1283457024 134512640 137933492 4290939520 18446744073709551615 4294960130 0 134217728 4096 0 18446744071696460772 0 0 17 0 0 0 0
/proc/19158/statm: 27103 7737 7643 836 0 65 0
Current children cumulated CPU time (s) 10.26
Current children cumulated vsize (KiB) 111008

[startup+25.5107 s]
/proc/loadavg: 1.09 1.13 1.10 2/48 19162
/proc/meminfo: memFree=522788/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=8.88
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 703 34598 0 1 0 0 856 32 19 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19158] ppid=19137 vsize=147500 CPUtime=14.12
/proc/19158/stat : 19158 (aptitude) S 19137 19137 2059 34821 2220 4202496 39648 650 388 0 1394 18 0 0 15 0 2 0 875909710 151040000 30749 1283457024 134512640 137933492 4290939520 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/19158/statm: 36875 30749 7709 836 0 27386 0
[pid=19158/tid=19160] ppid=19137 vsize=147500 CPUtime=10.12
/proc/19158/task/19160/stat : 19160 (aptitude) R 19137 19137 2059 34821 2220 4202560 20160 650 0 0 1006 6 0 0 25 0 2 0 875910032 151040000 30749 1283457024 134512640 137933492 4290939520 18446744073709551615 136432769 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 23
Current children cumulated vsize (KiB) 150096

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

[startup+25.7107 s]
/proc/loadavg: 1.09 1.13 1.10 2/48 19162
/proc/meminfo: memFree=522788/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=8.88
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 703 34598 0 1 0 0 856 32 19 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19158] ppid=19137 vsize=148424 CPUtime=14.32
/proc/19158/stat : 19158 (aptitude) S 19137 19137 2059 34821 2220 4202496 39894 650 388 0 1414 18 0 0 15 0 2 0 875909710 151986176 30995 1283457024 134512640 137933492 4290939520 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/19158/statm: 37106 30995 7709 836 0 27617 0
[pid=19158/tid=19160] ppid=19137 vsize=148424 CPUtime=10.32
/proc/19158/task/19160/stat : 19160 (aptitude) R 19137 19137 2059 34821 2220 4202560 20406 650 0 0 1026 6 0 0 25 0 2 0 875910032 151986176 30995 1283457024 134512640 137933492 4290939520 18446744073709551615 4153551868 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 23.2
Current children cumulated vsize (KiB) 151020

[startup+38.5056 s]
/proc/loadavg: 1.08 1.12 1.10 2/48 19162
/proc/meminfo: memFree=462772/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=8.88
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 703 34598 0 1 0 0 856 32 19 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19158] ppid=19137 vsize=211452 CPUtime=27.11
/proc/19158/stat : 19158 (aptitude) S 19137 19137 2059 34821 2220 4202496 55636 650 388 0 2685 26 0 0 15 0 2 0 875909710 216526848 46737 1283457024 134512640 137933492 4290939520 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/19158/statm: 52863 46737 7710 836 0 43374 0
[pid=19158/tid=19160] ppid=19137 vsize=211452 CPUtime=23.1
/proc/19158/task/19160/stat : 19160 (aptitude) R 19137 19137 2059 34821 2220 4202560 36147 650 0 0 2297 13 0 0 25 0 2 0 875910032 216526848 46737 1283457024 134512640 137933492 4290939520 18446744073709551615 134746352 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 35.99
Current children cumulated vsize (KiB) 214048

[startup+44.8969 s]
/proc/loadavg: 1.07 1.12 1.10 2/48 19162
/proc/meminfo: memFree=433260/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=8.88
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 703 34598 0 1 0 0 856 32 19 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19158] ppid=19137 vsize=238024 CPUtime=33.49
/proc/19158/stat : 19158 (aptitude) R 19137 19137 2059 34821 2220 4202496 62341 650 388 0 3323 26 0 0 16 0 2 0 875909710 243736576 53438 1283457024 134512640 137933492 4290939520 18446744073709551615 4153551979 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/19158/statm: 59506 53438 7753 836 0 50010 0
[pid=19158/tid=19160] ppid=19137 vsize=238024 CPUtime=29.11
/proc/19158/task/19160/stat : 19160 (aptitude) R 19137 19137 2059 34821 2220 4202560 42791 650 0 0 2897 14 0 0 25 0 2 0 875910032 243736576 53438 1283457024 134512640 137933492 4290939520 18446744073709551615 4294960130 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 42.37
Current children cumulated vsize (KiB) 240620

[startup+48.008 s]
/proc/loadavg: 1.15 1.13 1.10 2/47 19164
/proc/meminfo: memFree=589384/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=43.58
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 731 100249 0 389 0 0 4289 69 18 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19164] ppid=19137 vsize=41772 CPUtime=1.9
/proc/19164/stat : 19164 (aptsolutions.na) R 19137 19137 2059 34821 2220 4202496 10017 0 0 0 184 6 0 0 25 0 1 0 875913314 42774528 9902 1283457024 134512640 134971616 4291817248 18446744073709551615 134927670 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19164/statm: 10443 9902 204 113 0 9845 0
Current children cumulated CPU time (s) 45.48
Current children cumulated vsize (KiB) 44368

[startup+48.8082 s]
/proc/loadavg: 1.15 1.13 1.10 2/47 19164
/proc/meminfo: memFree=568056/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=43.58
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 731 100249 0 389 0 0 4289 69 18 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19164] ppid=19137 vsize=56652 CPUtime=2.7
/proc/19164/stat : 19164 (aptsolutions.na) R 19137 19137 2059 34821 2220 4202496 13690 0 0 0 264 6 0 0 25 0 1 0 875913314 58011648 13575 1283457024 134512640 134971616 4291817248 18446744073709551615 134929096 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19164/statm: 14163 13575 204 113 0 13565 0
Current children cumulated CPU time (s) 46.28
Current children cumulated vsize (KiB) 59248

[startup+49.2083 s]
/proc/loadavg: 1.15 1.13 1.10 2/47 19164
/proc/meminfo: memFree=568056/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=43.58
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 731 100249 0 389 0 0 4289 69 18 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19164] ppid=19137 vsize=64100 CPUtime=3.1
/proc/19164/stat : 19164 (aptsolutions.na) R 19137 19137 2059 34821 2220 4202496 15460 0 0 0 302 8 0 0 25 0 1 0 875913314 65638400 15345 1283457024 134512640 134971616 4291817248 18446744073709551615 134915911 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19164/statm: 16025 15345 204 113 0 15427 0
Current children cumulated CPU time (s) 46.68
Current children cumulated vsize (KiB) 66696

[startup+49.6084 s]
/proc/loadavg: 1.15 1.13 1.10 2/47 19164
/proc/meminfo: memFree=547844/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=43.58
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 731 100249 0 389 0 0 4289 69 18 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19164] ppid=19137 vsize=73584 CPUtime=3.5
/proc/19164/stat : 19164 (aptsolutions.na) R 19137 19137 2059 34821 2220 4202496 17779 0 0 0 339 11 0 0 25 0 1 0 875913314 75350016 17664 1283457024 134512640 134971616 4291817248 18446744073709551615 134917818 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19164/statm: 18396 17664 208 113 0 17798 0
Current children cumulated CPU time (s) 47.08
Current children cumulated vsize (KiB) 76180

[startup+49.7084 s]
/proc/loadavg: 1.15 1.13 1.10 2/47 19164
/proc/meminfo: memFree=547844/1048576 swapFree=2078744/2097144
[pid=19137] ppid=19136 vsize=2596 CPUtime=43.58
/proc/19137/stat : 19137 (aptitude-parano) S 19136 19137 2059 34821 2220 4202496 731 100249 0 389 0 0 4289 69 18 0 1 0 875908705 2658304 295 1283457024 134512640 135304128 4287306368 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19137/statm: 649 295 249 194 0 35 0
[pid=19164] ppid=19137 vsize=77312 CPUtime=3.6
/proc/19164/stat : 19164 (aptsolutions.na) R 19137 19137 2059 34821 2220 4202496 18690 0 0 0 349 11 0 0 25 0 1 0 875913314 79167488 18575 1283457024 134512640 134971616 4291817248 18446744073709551615 134912812 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19164/statm: 19328 18575 209 113 0 18730 0
Current children cumulated CPU time (s) 47.18
Current children cumulated vsize (KiB) 79908

Child status: 0
Real time (s): 49.7678
CPU time (s): 47.247
CPU user time (s): 46.4349
CPU system time (s): 0.81205
CPU usage (%): 94.9347
Max. virtual memory (cumulated for all children) (KiB): 243228

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 46.4349
system time used= 0.81205
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 120422
page faults= 389
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 352
involuntary context switches= 808

runsolver used 0 second user time and 0 second system time

The end