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/apt-get-trendy-1.0/rand108.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./apt-get-trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand108.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/apt-get-trendy-1.0/rand108.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: 0.95 0.99 0.99 4/44 5747
/proc/meminfo: memFree=689376/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2572 CPUtime=0
/proc/5746/stat : 5746 (apt-get-trendy-) R 5745 5746 4159 34819 4229 4202496 358 0 0 0 0 0 0 0 25 0 1 0 877865558 2633728 272 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/5746/statm: 643 272 232 194 0 29 0
[pid=5747] ppid=5746 vsize=2572 CPUtime=0
/proc/5747/stat : 5747 (apt-get-trendy-) R 5746 5746 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 877865558 2633728 40 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/5747/statm: 643 40 0 194 0 29 0

[startup+0.168482 s]
/proc/loadavg: 0.95 0.99 0.99 4/44 5747
/proc/meminfo: memFree=689376/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2584 CPUtime=0
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 509 1358 0 0 0 0 0 0 25 0 1 0 877865558 2646016 280 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 646 280 237 194 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2584

[startup+0.204701 s]
/proc/loadavg: 0.95 0.99 0.99 4/44 5747
/proc/meminfo: memFree=689376/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2584 CPUtime=0
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 509 1358 0 0 0 0 0 0 25 0 1 0 877865558 2646016 280 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 646 280 237 194 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2584

[startup+0.304505 s]
/proc/loadavg: 0.95 0.99 0.99 4/44 5747
/proc/meminfo: memFree=689376/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2584 CPUtime=0
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 509 1358 0 0 0 0 0 0 25 0 1 0 877865558 2646016 280 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 646 280 237 194 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2584

[startup+0.710282 s]
/proc/loadavg: 0.95 0.99 0.99 4/44 5747
/proc/meminfo: memFree=689376/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2584 CPUtime=0.01
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 555 1858 0 0 0 0 0 1 22 0 1 0 877865558 2646016 283 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2584

[startup+1.51046 s]
/proc/loadavg: 0.95 0.99 0.99 2/45 5757
/proc/meminfo: memFree=636640/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2584 CPUtime=0.01
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 555 1858 0 0 0 0 0 1 22 0 1 0 877865558 2646016 283 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 646 283 240 194 0 32 0
[pid=5757] ppid=5746 vsize=24824 CPUtime=1.06
/proc/5757/stat : 5757 (cudftodeb.nativ) R 5746 5746 4159 34819 4229 4202496 5821 0 3 0 102 4 0 0 25 0 1 0 877865600 25419776 5751 1283457024 134512640 135004320 4288606464 18446744073709551615 134949662 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5757/statm: 6206 5751 225 121 0 5598 0
Current children cumulated CPU time (s) 1.07
Current children cumulated vsize (KiB) 27408

[startup+3.11082 s]
/proc/loadavg: 0.95 0.99 0.99 2/45 5757
/proc/meminfo: memFree=614692/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2584 CPUtime=0.01
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 555 1858 0 0 0 0 0 1 22 0 1 0 877865558 2646016 283 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 646 283 240 194 0 32 0
[pid=5757] ppid=5746 vsize=56944 CPUtime=2.66
/proc/5757/stat : 5757 (cudftodeb.nativ) R 5746 5746 4159 34819 4229 4202496 13715 0 3 0 260 6 0 0 25 0 1 0 877865600 58310656 13645 1283457024 134512640 135004320 4288606464 18446744073709551615 134948002 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5757/statm: 14236 13645 225 121 0 13628 0
Current children cumulated CPU time (s) 2.67
Current children cumulated vsize (KiB) 59528

[startup+6.31164 s]
/proc/loadavg: 0.96 0.99 0.99 2/45 5757
/proc/meminfo: memFree=549964/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2584 CPUtime=0.01
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 555 1858 0 0 0 0 0 1 22 0 1 0 877865558 2646016 283 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 646 283 240 194 0 32 0
[pid=5757] ppid=5746 vsize=111248 CPUtime=5.85
/proc/5757/stat : 5757 (cudftodeb.nativ) R 5746 5746 4159 34819 4229 4202496 27049 0 3 0 569 16 0 0 25 0 1 0 877865600 113917952 26979 1283457024 134512640 135004320 4288606464 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5757/statm: 27812 26979 237 121 0 27204 0
Current children cumulated CPU time (s) 5.86
Current children cumulated vsize (KiB) 113832

[startup+12.7053 s]
/proc/loadavg: 0.96 0.99 0.99 1/45 5767
/proc/meminfo: memFree=546588/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2592 CPUtime=8.75
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 690 34696 0 4 0 1 842 32 18 0 1 0 877865558 2654208 294 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 648 294 249 194 0 34 0
[pid=5767] ppid=5746 vsize=101456 CPUtime=1.36
/proc/5767/stat : 5767 (apt-get) D 5746 5746 4159 34819 4229 4202496 6951 0 388 0 126 10 0 0 18 0 1 0 877866596 103890944 7263 1283457024 134512640 134619611 4289440256 18446744073709551615 4294960130 0 0 4096 134217728 18446744071564332537 0 0 17 0 0 0 0
/proc/5767/statm: 25364 7263 7210 27 0 58 0
Current children cumulated CPU time (s) 10.11
Current children cumulated vsize (KiB) 104048
heavy processes:

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

[startup+12.8053 s]
/proc/loadavg: 0.96 0.99 0.99 1/45 5767
/proc/meminfo: memFree=545676/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2592 CPUtime=8.75
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 690 34696 0 4 0 1 842 32 18 0 1 0 877865558 2654208 294 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 648 294 249 194 0 34 0
[pid=5767] ppid=5746 vsize=101456 CPUtime=1.36
/proc/5767/stat : 5767 (apt-get) D 5746 5746 4159 34819 4229 4202496 6951 0 388 0 126 10 0 0 18 0 1 0 877866596 103890944 7263 1283457024 134512640 134619611 4289440256 18446744073709551615 4294960130 0 0 4096 134217728 18446744071564332537 0 0 17 0 0 0 0
/proc/5767/statm: 25364 7263 7210 27 0 58 0
Current children cumulated CPU time (s) 10.11
Current children cumulated vsize (KiB) 104048

[startup+13.6057 s]
/proc/loadavg: 0.96 0.99 0.99 2/45 5767
/proc/meminfo: memFree=543196/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2592 CPUtime=8.75
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 690 34696 0 4 0 1 842 32 18 0 1 0 877865558 2654208 294 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 648 294 249 194 0 34 0
[pid=5767] ppid=5746 vsize=34296 CPUtime=2.08
/proc/5767/stat : 5767 (apt-get) R 5746 5746 4159 34819 4229 4202496 14237 0 388 0 196 12 0 0 18 0 1 0 877866596 35119104 7646 1283457024 134512640 134619611 4289440256 18446744073709551615 4159138931 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/5767/statm: 8574 7646 6872 27 0 817 0
Current children cumulated CPU time (s) 10.83
Current children cumulated vsize (KiB) 36888

[startup+13.8057 s]
/proc/loadavg: 0.96 0.99 0.99 2/45 5767
/proc/meminfo: memFree=543196/1048576 swapFree=2077676/2097144
[pid=5746] ppid=5745 vsize=2592 CPUtime=8.75
/proc/5746/stat : 5746 (apt-get-trendy-) S 5745 5746 4159 34819 4229 4202496 690 34696 0 4 0 1 842 32 18 0 1 0 877865558 2654208 294 1283457024 134512640 135304128 4293009408 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5746/statm: 648 294 249 194 0 34 0
[pid=5767] ppid=5746 vsize=34296 CPUtime=2.28
/proc/5767/stat : 5767 (apt-get) R 5746 5746 4159 34819 4229 4202496 14237 0 388 0 216 12 0 0 19 0 1 0 877866596 35119104 7646 1283457024 134512640 134619611 4289440256 18446744073709551615 4159225107 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/5767/statm: 8574 7646 6872 27 0 817 0
Current children cumulated CPU time (s) 11.03
Current children cumulated vsize (KiB) 36888

Child status: 100
Real time (s): 13.8649
CPU time (s): 11.0967
CPU user time (s): 10.6367
CPU system time (s): 0.460028
CPU usage (%): 80.0346
Max. virtual memory (cumulated for all children) (KiB): 124000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 10.6367
system time used= 0.460028
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 49644
page faults= 392
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 388
involuntary context switches= 201

runsolver used 0 second user time and 0.008 second system time

The end