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/rand550.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./apt-get-trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand550.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/apt-get-trendy-1.0/rand550.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.93 1.01 1.05 1/43 19875
/proc/meminfo: memFree=763764/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=3020 CPUtime=0
/proc/19875/stat : 19875 (runsolver) D 19874 19875 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 881488761 3092480 93 1283457024 134512640 134586868 4292001312 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/19875/statm: 755 93 62 19 0 53 0

[startup+0.189954 s]
/proc/loadavg: 0.93 1.01 1.05 1/43 19875
/proc/meminfo: memFree=763764/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2584 CPUtime=0
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 518 1364 0 0 0 0 0 0 25 0 1 0 881488761 2646016 281 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 646 281 237 194 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2584

[startup+0.205836 s]
/proc/loadavg: 0.93 1.01 1.05 1/43 19875
/proc/meminfo: memFree=763764/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2584 CPUtime=0
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 518 1364 0 0 0 0 0 0 25 0 1 0 881488761 2646016 281 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 646 281 237 194 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2584

[startup+0.305861 s]
/proc/loadavg: 0.93 1.01 1.05 1/43 19875
/proc/meminfo: memFree=763764/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2584 CPUtime=0
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 518 1364 0 0 0 0 0 0 25 0 1 0 881488761 2646016 281 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 646 281 237 194 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2584

[startup+0.705954 s]
/proc/loadavg: 0.93 1.01 1.05 1/43 19875
/proc/meminfo: memFree=763764/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2584 CPUtime=0.01
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 566 1860 0 4 0 0 0 1 22 0 1 0 881488761 2646016 284 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2584

[startup+1.5061 s]
/proc/loadavg: 0.93 1.01 1.05 2/45 19886
/proc/meminfo: memFree=710032/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2584 CPUtime=0.01
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 566 1860 0 4 0 0 0 1 22 0 1 0 881488761 2646016 284 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 646 284 240 194 0 32 0
[pid=19886] ppid=19875 vsize=24820 CPUtime=1.05
/proc/19886/stat : 19886 (cudftodeb.nativ) R 19875 19875 4159 34819 4229 4202496 5760 0 8 0 103 2 0 0 25 0 1 0 881488801 25415680 5694 1283457024 134512640 135004320 4293860064 18446744073709551615 134961339 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19886/statm: 6205 5694 225 121 0 5597 0
Current children cumulated CPU time (s) 1.06
Current children cumulated vsize (KiB) 27404

[startup+3.10642 s]
/proc/loadavg: 0.93 1.01 1.05 2/45 19886
/proc/meminfo: memFree=687836/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2584 CPUtime=0.01
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 566 1860 0 4 0 0 0 1 22 0 1 0 881488761 2646016 284 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 646 284 240 194 0 32 0
[pid=19886] ppid=19875 vsize=56940 CPUtime=2.65
/proc/19886/stat : 19886 (cudftodeb.nativ) R 19875 19875 4159 34819 4229 4202496 13710 0 8 0 261 4 0 0 25 0 1 0 881488801 58306560 13644 1283457024 134512640 135004320 4293860064 18446744073709551615 134828061 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19886/statm: 14235 13644 225 121 0 13627 0
Current children cumulated CPU time (s) 2.66
Current children cumulated vsize (KiB) 59524

[startup+6.30717 s]
/proc/loadavg: 0.94 1.01 1.05 2/45 19886
/proc/meminfo: memFree=622984/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2584 CPUtime=0.01
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 566 1860 0 4 0 0 0 1 22 0 1 0 881488761 2646016 284 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 646 284 240 194 0 32 0
[pid=19886] ppid=19875 vsize=111248 CPUtime=5.84
/proc/19886/stat : 19886 (cudftodeb.nativ) R 19875 19875 4159 34819 4229 4202496 26986 0 8 0 562 22 0 0 25 0 1 0 881488801 113917952 26920 1283457024 134512640 135004320 4293860064 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19886/statm: 27812 26920 237 121 0 27204 0
Current children cumulated CPU time (s) 5.85
Current children cumulated vsize (KiB) 113832

[startup+12.7067 s]
/proc/loadavg: 0.94 1.01 1.05 2/45 19896
/proc/meminfo: memFree=618704/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2592 CPUtime=8.82
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 705 34679 0 24 0 0 842 40 18 0 1 0 881488761 2654208 295 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 648 295 249 194 0 34 0
[pid=19896] ppid=19875 vsize=101452 CPUtime=1.35
/proc/19896/stat : 19896 (apt-get) D 19875 19875 4159 34819 4229 4202496 6952 0 388 0 126 9 0 0 18 0 1 0 881489809 103886848 7263 1283457024 134512640 134619611 4289843776 18446744073709551615 4294960130 0 0 4096 134217728 18446744071564332537 0 0 17 0 0 0 0
/proc/19896/statm: 25363 7263 7210 27 0 57 0
Current children cumulated CPU time (s) 10.17
Current children cumulated vsize (KiB) 104044

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

[startup+12.8066 s]
/proc/loadavg: 0.94 1.01 1.05 2/45 19896
/proc/meminfo: memFree=618704/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2592 CPUtime=8.82
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 705 34679 0 24 0 0 842 40 18 0 1 0 881488761 2654208 295 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 648 295 249 194 0 34 0
[pid=19896] ppid=19875 vsize=101452 CPUtime=1.35
/proc/19896/stat : 19896 (apt-get) D 19875 19875 4159 34819 4229 4202496 6952 0 388 0 126 9 0 0 18 0 1 0 881489809 103886848 7263 1283457024 134512640 134619611 4289843776 18446744073709551615 4294960130 0 0 4096 134217728 18446744071564332537 0 0 17 0 0 0 0
/proc/19896/statm: 25363 7263 7210 27 0 57 0
Current children cumulated CPU time (s) 10.17
Current children cumulated vsize (KiB) 104044

[startup+16.0116 s]
/proc/loadavg: 0.95 1.01 1.05 2/45 19896
/proc/meminfo: memFree=613144/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2592 CPUtime=8.82
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 705 34679 0 24 0 0 842 40 18 0 1 0 881488761 2654208 295 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 648 295 249 194 0 34 0
[pid=19896] ppid=19875 vsize=36176 CPUtime=4.13
/proc/19896/stat : 19896 (apt-get) R 19875 19875 4159 34819 4229 4202496 14745 0 388 0 400 13 0 0 22 0 1 0 881489809 37044224 8110 1283457024 134512640 134619611 4289843776 18446744073709551615 4159415387 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/19896/statm: 9044 8110 6887 27 0 1287 0
Current children cumulated CPU time (s) 12.95
Current children cumulated vsize (KiB) 38768

[startup+17.6066 s]
/proc/loadavg: 0.95 1.01 1.05 2/45 19897
/proc/meminfo: memFree=591652/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2592 CPUtime=13.27
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 726 49454 0 412 0 0 1273 54 20 0 1 0 881488761 2654208 295 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 648 295 249 194 0 34 0
[pid=19897] ppid=19875 vsize=28676 CPUtime=1.24
/proc/19897/stat : 19897 (aptsolutions.na) R 19875 19875 4159 34819 4229 4202496 6742 0 8 0 122 2 0 0 25 0 1 0 881490393 29364224 6636 1283457024 134512640 134971616 4294879760 18446744073709551615 134623606 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19897/statm: 7169 6636 204 113 0 6571 0
Current children cumulated CPU time (s) 14.51
Current children cumulated vsize (KiB) 31268

[startup+19.2069 s]
/proc/loadavg: 0.95 1.01 1.05 2/45 19897
/proc/meminfo: memFree=570324/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2592 CPUtime=13.27
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 726 49454 0 412 0 0 1273 54 20 0 1 0 881488761 2654208 295 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 648 295 249 194 0 34 0
[pid=19897] ppid=19875 vsize=58632 CPUtime=2.84
/proc/19897/stat : 19897 (aptsolutions.na) R 19875 19875 4159 34819 4229 4202496 14147 0 8 0 280 4 0 0 25 0 1 0 881490393 60039168 14039 1283457024 134512640 134971616 4294879760 18446744073709551615 134954131 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19897/statm: 14658 14039 204 113 0 14060 0
Current children cumulated CPU time (s) 16.11
Current children cumulated vsize (KiB) 61224

[startup+19.6071 s]
/proc/loadavg: 0.95 1.01 1.05 2/45 19897
/proc/meminfo: memFree=570324/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2592 CPUtime=13.27
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 726 49454 0 412 0 0 1273 54 20 0 1 0 881488761 2654208 295 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 648 295 249 194 0 34 0
[pid=19897] ppid=19875 vsize=66824 CPUtime=3.24
/proc/19897/stat : 19897 (aptsolutions.na) R 19875 19875 4159 34819 4229 4202496 16106 0 8 0 320 4 0 0 25 0 1 0 881490393 68427776 15998 1283457024 134512640 134971616 4294879760 18446744073709551615 134601871 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19897/statm: 16706 15998 204 113 0 16108 0
Current children cumulated CPU time (s) 16.51
Current children cumulated vsize (KiB) 69416

[startup+20.0072 s]
/proc/loadavg: 0.95 1.01 1.05 2/45 19897
/proc/meminfo: memFree=549864/1048576 swapFree=2077680/2097144
[pid=19875] ppid=19874 vsize=2592 CPUtime=13.27
/proc/19875/stat : 19875 (apt-get-trendy-) S 19874 19875 4159 34819 4229 4202496 726 49454 0 412 0 0 1273 54 20 0 1 0 881488761 2654208 295 1283457024 134512640 135304128 4289102912 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19875/statm: 648 295 249 194 0 34 0
[pid=19897] ppid=19875 vsize=77556 CPUtime=3.64
/proc/19897/stat : 19897 (aptsolutions.na) R 19875 19875 4159 34819 4229 4202496 18789 0 8 0 360 4 0 0 25 0 1 0 881490393 79417344 18681 1283457024 134512640 134971616 4294879760 18446744073709551615 134964240 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19897/statm: 19389 18681 209 113 0 18791 0
Current children cumulated CPU time (s) 16.91
Current children cumulated vsize (KiB) 80148

Child status: 0
Real time (s): 20.046
CPU time (s): 16.9651
CPU user time (s): 16.369
CPU system time (s): 0.596037
CPU usage (%): 84.6305
Max. virtual memory (cumulated for all children) (KiB): 124000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 16.369
system time used= 0.596037
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 69682
page faults= 420
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 450
involuntary context switches= 273

runsolver used 0 second user time and 0.004 second system time

The end