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/rand316.sarge.cudf.sarge.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/icse/sarge/rand316.sarge.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand316.sarge.cudf.sarge.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.52 1.21 1.11 4/45 12244
/proc/meminfo: memFree=803088/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2580 CPUtime=0.02
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 555 1856 0 0 0 0 0 2 25 0 1 0 875328620 2641920 282 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 645 282 240 194 0 31 0
[pid=12244] ppid=12234 vsize=3512 CPUtime=0.02
/proc/12244/stat : 12244 (cudftodeb.nativ) R 12234 12234 2059 34821 2220 4202496 545 0 0 0 2 0 0 0 25 0 1 0 875328622 3596288 472 1283457024 134512640 135004320 4293017744 18446744073709551615 134977561 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12244/statm: 878 472 224 121 0 270 0

[startup+0.232651 s]
/proc/loadavg: 1.52 1.21 1.11 4/45 12244
/proc/meminfo: memFree=803088/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2580 CPUtime=0.02
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 555 1856 0 0 0 0 0 2 25 0 1 0 875328620 2641920 282 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 645 282 240 194 0 31 0
[pid=12244] ppid=12234 vsize=7480 CPUtime=0.22
/proc/12244/stat : 12244 (cudftodeb.nativ) R 12234 12234 2059 34821 2220 4202496 1552 0 0 0 20 2 0 0 25 0 1 0 875328622 7659520 1479 1283457024 134512640 135004320 4293017744 18446744073709551615 4158879267 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12244/statm: 1870 1479 225 121 0 1262 0
Current children cumulated CPU time (s) 0.24
Current children cumulated vsize (KiB) 10060

[startup+0.312665 s]
/proc/loadavg: 1.52 1.21 1.11 4/45 12244
/proc/meminfo: memFree=803088/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2580 CPUtime=0.02
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 555 1856 0 0 0 0 0 2 25 0 1 0 875328620 2641920 282 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 645 282 240 194 0 31 0
[pid=12244] ppid=12234 vsize=9216 CPUtime=0.3
/proc/12244/stat : 12244 (cudftodeb.nativ) R 12234 12234 2059 34821 2220 4202496 1958 0 0 0 28 2 0 0 25 0 1 0 875328622 9437184 1885 1283457024 134512640 135004320 4293017744 18446744073709551615 134828448 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12244/statm: 2304 1885 225 121 0 1696 0
Current children cumulated CPU time (s) 0.32
Current children cumulated vsize (KiB) 11796

[startup+0.412682 s]
/proc/loadavg: 1.52 1.21 1.11 4/45 12244
/proc/meminfo: memFree=803088/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2580 CPUtime=0.02
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 555 1856 0 0 0 0 0 2 25 0 1 0 875328620 2641920 282 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 645 282 240 194 0 31 0
[pid=12244] ppid=12234 vsize=11360 CPUtime=0.4
/proc/12244/stat : 12244 (cudftodeb.nativ) R 12234 12234 2059 34821 2220 4202496 2459 0 0 0 38 2 0 0 25 0 1 0 875328622 11632640 2386 1283457024 134512640 135004320 4293017744 18446744073709551615 134950962 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12244/statm: 2840 2386 225 121 0 2232 0
Current children cumulated CPU time (s) 0.42
Current children cumulated vsize (KiB) 13940

[startup+0.712756 s]
/proc/loadavg: 1.52 1.21 1.11 4/45 12244
/proc/meminfo: memFree=803088/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2580 CPUtime=0.02
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 555 1856 0 0 0 0 0 2 25 0 1 0 875328620 2641920 282 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 645 282 240 194 0 31 0
[pid=12244] ppid=12234 vsize=18304 CPUtime=0.7
/proc/12244/stat : 12244 (cudftodeb.nativ) R 12234 12234 2059 34821 2220 4202496 4184 0 0 0 68 2 0 0 25 0 1 0 875328622 18743296 4111 1283457024 134512640 135004320 4293017744 18446744073709551615 4159989952 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12244/statm: 4576 4111 236 121 0 3968 0
Current children cumulated CPU time (s) 0.72
Current children cumulated vsize (KiB) 20884

[startup+1.51293 s]
/proc/loadavg: 1.47 1.20 1.11 2/46 12245
/proc/meminfo: memFree=777684/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2588 CPUtime=1.47
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 635 8994 0 0 0 0 140 7 22 0 1 0 875328620 2650112 285 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 647 285 241 194 0 33 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 2588

[startup+3.10571 s]
/proc/loadavg: 1.47 1.20 1.11 1/46 12256
/proc/meminfo: memFree=784008/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2588 CPUtime=1.54
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 680 11391 0 1 0 0 146 8 18 0 1 0 875328620 2650112 293 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 647 293 249 194 0 33 0
[pid=12255] ppid=12234 vsize=38336 CPUtime=0.63
/proc/12255/stat : 12255 (aptitude) R 12234 12234 2059 34821 2220 4202496 5782 650 82 0 58 4 1 0 21 0 2 0 875328824 39256064 3917 1283457024 134512640 137933492 4294020480 18446744073709551615 136695889 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/12255/statm: 9584 3917 2554 836 0 5496 0
Current children cumulated CPU time (s) 2.17
Current children cumulated vsize (KiB) 40924
heavy processes:

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

[startup+3.30572 s]
/proc/loadavg: 1.47 1.20 1.11 2/47 12259
/proc/meminfo: memFree=778188/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2588 CPUtime=1.54
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 680 11391 0 1 0 0 146 8 18 0 1 0 875328620 2650112 293 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 647 293 249 194 0 33 0
[pid=12255] ppid=12234 vsize=39524 CPUtime=0.83
/proc/12255/stat : 12255 (aptitude) R 12234 12234 2059 34821 2220 4202496 6353 650 82 0 78 4 1 0 21 0 2 0 875328824 40472576 4310 1283457024 134512640 137933492 4294020480 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/12255/statm: 9881 4310 2601 836 0 5793 0
[pid=12255/tid=12257] ppid=12234 vsize=39524 CPUtime=0.11
/proc/12255/task/12257/stat : 12257 (aptitude) R 12234 12234 2059 34821 2220 4202560 572 650 0 0 10 0 1 0 17 0 2 0 875328903 40472576 4310 1283457024 134512640 137933492 4294020480 18446744073709551615 4153005872 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 2.37
Current children cumulated vsize (KiB) 42112

[startup+4.10585 s]
/proc/loadavg: 1.47 1.20 1.11 3/47 12259
/proc/meminfo: memFree=775832/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2588 CPUtime=3.15
/proc/12234/stat : 12234 (aptitude-parano) R 12233 12234 2059 34821 2220 4202496 689 20899 0 83 0 0 301 14 18 0 1 0 875328620 2650112 293 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/12234/statm: 647 293 249 194 0 33 0
Current children cumulated CPU time (s) 3.15
Current children cumulated vsize (KiB) 2588

[startup+4.50597 s]
/proc/loadavg: 1.47 1.20 1.11 2/46 12261
/proc/meminfo: memFree=774476/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2588 CPUtime=3.15
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 705 20899 0 83 0 0 301 14 18 0 1 0 875328620 2650112 293 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 647 293 249 194 0 33 0
[pid=12261] ppid=12234 vsize=12064 CPUtime=0.43
/proc/12261/stat : 12261 (aptsolutions.na) R 12234 12234 2059 34821 2220 4202496 2653 0 0 0 43 0 0 0 21 0 1 0 875329028 12353536 2540 1283457024 134512640 134971616 4290557456 18446744073709551615 134954215 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12261/statm: 3016 2540 204 113 0 2418 0
Current children cumulated CPU time (s) 3.58
Current children cumulated vsize (KiB) 14652

[startup+4.706 s]
/proc/loadavg: 1.47 1.20 1.11 2/46 12261
/proc/meminfo: memFree=774476/1048576 swapFree=2078820/2097144
[pid=12234] ppid=12233 vsize=2588 CPUtime=3.15
/proc/12234/stat : 12234 (aptitude-parano) S 12233 12234 2059 34821 2220 4202496 705 20899 0 83 0 0 301 14 18 0 1 0 875328620 2650112 293 1283457024 134512640 135304128 4291530448 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12234/statm: 647 293 249 194 0 33 0
[pid=12261] ppid=12234 vsize=16280 CPUtime=0.63
/proc/12261/stat : 12261 (aptsolutions.na) R 12234 12234 2059 34821 2220 4202496 3704 0 0 0 63 0 0 0 22 0 1 0 875329028 16670720 3591 1283457024 134512640 134971616 4290557456 18446744073709551615 134800678 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12261/statm: 4070 3591 204 113 0 3472 0
Current children cumulated CPU time (s) 3.78
Current children cumulated vsize (KiB) 18868

Child status: 0
Real time (s): 4.78161
CPU time (s): 3.86024
CPU user time (s): 3.71223
CPU system time (s): 0.148009
CPU usage (%): 80.7309
Max. virtual memory (cumulated for all children) (KiB): 110996

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.71223
system time used= 0.148009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 26137
page faults= 83
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 192
involuntary context switches= 171

runsolver used 0 second user time and 0 second system time

The end