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/201012070034/aptitude-trendy-1.0/rand815.sarge.cudf.sarge.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/icse/sarge/rand815.sarge.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand815.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: 0.88 0.99 1.04 5/45 26242
/proc/meminfo: memFree=833764/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2576 CPUtime=0
/proc/26241/stat : 26241 (aptitude-trendy) R 26240 26241 4159 34819 4229 4202496 360 0 0 0 0 0 0 0 25 0 1 0 882967138 2637824 273 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/26241/statm: 644 273 232 194 0 30 0
[pid=26242] ppid=26241 vsize=2576 CPUtime=0
/proc/26242/stat : 26242 (aptitude-trendy) R 26241 26241 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 882967138 2637824 41 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/26242/statm: 644 41 0 194 0 30 0

[startup+0.189032 s]
/proc/loadavg: 0.88 0.99 1.04 5/45 26242
/proc/meminfo: memFree=833764/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2588 CPUtime=0.02
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 568 1862 0 0 0 0 0 2 25 0 1 0 882967138 2650112 284 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.209052 s]
/proc/loadavg: 0.88 0.99 1.04 5/45 26242
/proc/meminfo: memFree=833764/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2588 CPUtime=0.02
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 568 1862 0 0 0 0 0 2 25 0 1 0 882967138 2650112 284 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.309094 s]
/proc/loadavg: 0.88 0.99 1.04 5/45 26242
/proc/meminfo: memFree=833764/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2588 CPUtime=0.02
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 568 1862 0 0 0 0 0 2 25 0 1 0 882967138 2650112 284 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.709224 s]
/proc/loadavg: 0.88 0.99 1.04 5/45 26242
/proc/meminfo: memFree=833764/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2588 CPUtime=0.02
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 568 1862 0 0 0 0 0 2 25 0 1 0 882967138 2650112 284 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+1.50939 s]
/proc/loadavg: 0.89 0.99 1.04 2/46 26252
/proc/meminfo: memFree=805168/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2596 CPUtime=1.46
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 650 9003 0 0 0 0 144 2 18 0 1 0 882967138 2658304 287 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 649 287 241 194 0 35 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 2596

[startup+3.10839 s]
/proc/loadavg: 0.89 0.99 1.04 2/46 26263
/proc/meminfo: memFree=816360/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2596 CPUtime=1.53
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 693 11397 0 1 0 0 150 3 18 0 1 0 882967138 2658304 295 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 649 295 249 194 0 35 0
[pid=26262] ppid=26241 vsize=38344 CPUtime=0.73
/proc/26262/stat : 26262 (aptitude) R 26241 26241 4159 34819 4229 4202496 6038 649 82 0 71 2 0 0 22 0 2 0 882967342 39264256 4036 1283457024 134512640 137933492 4289358112 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/26262/statm: 9586 4036 2605 836 0 5498 0
Current children cumulated CPU time (s) 2.26
Current children cumulated vsize (KiB) 40940
heavy processes:

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

[startup+3.20843 s]
/proc/loadavg: 0.89 0.99 1.04 3/47 26266
/proc/meminfo: memFree=804368/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2596 CPUtime=1.53
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 693 11397 0 1 0 0 150 3 18 0 1 0 882967138 2658304 295 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 649 295 249 194 0 35 0
[pid=26262] ppid=26241 vsize=39164 CPUtime=0.83
/proc/26262/stat : 26262 (aptitude) R 26241 26241 4159 34819 4229 4202496 7022 1059 82 0 80 3 0 0 23 0 2 0 882967342 40103936 4276 1283457024 134512640 137933492 4289358112 18446744073709551615 4159571805 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/26262/statm: 9791 4276 2664 836 0 5696 0
[pid=26262/tid=26264] ppid=26241 vsize=39164 CPUtime=0.07
/proc/26262/task/26264/stat : 26264 (aptitude) S 26241 26241 4159 34819 4229 4202560 416 1059 0 0 7 0 0 0 18 0 2 0 882967411 40103936 4276 1283457024 134512640 137933492 4289358112 18446744073709551615 4294960130 0 134217728 4096 0 18446612132440700096 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 2.36
Current children cumulated vsize (KiB) 41760

[startup+3.60849 s]
/proc/loadavg: 0.89 0.99 1.04 2/46 26268
/proc/meminfo: memFree=808716/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2596 CPUtime=2.42
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 721 19590 0 83 0 0 236 6 18 0 1 0 882967138 2658304 295 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 649 295 249 194 0 35 0
[pid=26268] ppid=26241 vsize=10416 CPUtime=0.34
/proc/26268/stat : 26268 (aptsolutions.na) R 26241 26241 4159 34819 4229 4202496 2279 0 0 0 34 0 0 0 21 0 1 0 882967465 10665984 2166 1283457024 134512640 134971616 4292013952 18446744073709551615 134945321 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26268/statm: 2604 2166 204 113 0 2006 0
Current children cumulated CPU time (s) 2.76
Current children cumulated vsize (KiB) 13012

[startup+4.0092 s]
/proc/loadavg: 0.89 0.99 1.04 2/46 26268
/proc/meminfo: memFree=808716/1048576 swapFree=2077184/2097144
[pid=26241] ppid=26240 vsize=2596 CPUtime=2.42
/proc/26241/stat : 26241 (aptitude-trendy) S 26240 26241 4159 34819 4229 4202496 721 19590 0 83 0 0 236 6 18 0 1 0 882967138 2658304 295 1283457024 134512640 135304128 4288697392 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26241/statm: 649 295 249 194 0 35 0
[pid=26268] ppid=26241 vsize=19712 CPUtime=0.74
/proc/26268/stat : 26268 (aptsolutions.na) R 26241 26241 4159 34819 4229 4202496 4601 0 0 0 73 1 0 0 22 0 1 0 882967465 20185088 4488 1283457024 134512640 134971616 4292013952 18446744073709551615 134912812 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26268/statm: 4928 4488 209 113 0 4330 0
Current children cumulated CPU time (s) 3.16
Current children cumulated vsize (KiB) 22308

Child status: 0
Real time (s): 4.05124
CPU time (s): 3.2202
CPU user time (s): 3.1282
CPU system time (s): 0.092005
CPU usage (%): 79.4868
Max. virtual memory (cumulated for all children) (KiB): 111008

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.12819
system time used= 0.092005
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25549
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= 201
involuntary context switches= 175

runsolver used 0 second user time and 0.008 second system time

The end