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/201103031013/apt-pbo-trendy-1.0.8/56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf.debian.log.runsolver ./apt-pbo-trendy-1.0.8 /home/misc2010/data/misc4/debian//56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf /home/misc2010/tmp/201103031013/apt-pbo-trendy-1.0.8/56ae4afa-0b33-11df-8a2b-00163e1d94dc.cudf.debian.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.24 1.08 1.06 3/36 32197
/proc/meminfo: memFree=529220/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) R 32195 32196 29493 34817 29493 4202496 207 0 0 0 0 0 0 0 25 0 1 0 75083679 1716224 127 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 0 0 0 17 0 0 0 0
/proc/32196/statm: 419 127 110 20 0 46 0
[pid=32197] ppid=32196 vsize=1676 CPUtime=0
/proc/32197/stat : 32197 (sh) R 32196 32196 29493 34817 29493 4202560 0 0 0 0 0 0 0 0 25 0 1 0 75083679 1716224 17 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 0 0 0 17 0 0 0 0
/proc/32197/statm: 419 17 0 20 0 46 0

[startup+0.147771 s]
/proc/loadavg: 1.24 1.08 1.06 3/36 32197
/proc/meminfo: memFree=529220/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.217586 s]
/proc/loadavg: 1.24 1.08 1.06 3/36 32197
/proc/meminfo: memFree=529220/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.307606 s]
/proc/loadavg: 1.24 1.08 1.06 3/36 32197
/proc/meminfo: memFree=529220/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.707701 s]
/proc/loadavg: 1.24 1.08 1.06 3/36 32197
/proc/meminfo: memFree=529220/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+1.50789 s]
/proc/loadavg: 1.30 1.10 1.07 2/38 32202
/proc/meminfo: memFree=507112/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
[pid=32199] ppid=32196 vsize=8232 CPUtime=0.05
/proc/32199/stat : 32199 (apt-pbo) S 32196 32196 29493 34817 29493 4202496 1585 411 0 0 3 2 0 0 25 0 1 0 75083679 8429568 1401 1283457024 134512640 135745756 4287701568 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/32199/statm: 2058 1401 648 302 0 791 0
[pid=32202] ppid=32199 vsize=29680 CPUtime=1.4
/proc/32202/stat : 32202 (cudftodeb.nativ) R 32199 32196 29493 34817 29493 4202496 6994 0 0 0 138 2 0 0 25 0 1 0 75083689 30392320 6915 1283457024 134512640 135029684 4290852272 18446744073709551615 4158387596 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/32202/statm: 7420 6915 246 127 0 6801 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 39588

[startup+3.10828 s]
/proc/loadavg: 1.30 1.10 1.07 2/38 32202
/proc/meminfo: memFree=486528/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
[pid=32199] ppid=32196 vsize=8232 CPUtime=0.05
/proc/32199/stat : 32199 (apt-pbo) S 32196 32196 29493 34817 29493 4202496 1585 411 0 0 3 2 0 0 25 0 1 0 75083679 8429568 1401 1283457024 134512640 135745756 4287701568 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/32199/statm: 2058 1401 648 302 0 791 0
[pid=32202] ppid=32199 vsize=58668 CPUtime=3
/proc/32202/stat : 32202 (cudftodeb.nativ) R 32199 32196 29493 34817 29493 4202496 14273 0 0 0 294 6 0 0 25 0 1 0 75083689 60076032 14194 1283457024 134512640 135029684 4290852272 18446744073709551615 135002680 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/32202/statm: 14667 14194 246 127 0 14048 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 68576

[startup+6.30891 s]
/proc/loadavg: 1.28 1.10 1.07 2/38 32203
/proc/meminfo: memFree=425024/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
[pid=32199] ppid=32196 vsize=8232 CPUtime=0.05
/proc/32199/stat : 32199 (apt-pbo) S 32196 32196 29493 34817 29493 4202496 1585 411 0 0 3 2 0 0 25 0 1 0 75083679 8429568 1401 1283457024 134512640 135745756 4287701568 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/32199/statm: 2058 1401 648 302 0 791 0
[pid=32202] ppid=32199 vsize=112348 CPUtime=6.19
/proc/32202/stat : 32202 (cudftodeb.nativ) R 32199 32196 29493 34817 29493 4202496 27488 0 0 0 584 35 0 0 25 0 1 0 75083689 115044352 27409 1283457024 134512640 135029684 4290852272 18446744073709551615 4294960130 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/32202/statm: 28087 27409 259 127 0 27468 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 122256

[startup+12.7045 s]
/proc/loadavg: 1.25 1.09 1.06 2/39 32211
/proc/meminfo: memFree=468540/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
[pid=32199] ppid=32196 vsize=8232 CPUtime=10.16
/proc/32199/stat : 32199 (apt-pbo) S 32196 32196 29493 34817 29493 4202496 1760 31101 0 0 3 2 881 130 18 0 1 0 75083679 8429568 1428 1283457024 134512640 135745756 4287701568 18446744073709551615 4294960130 0 0 135 0 18446744071564329979 0 0 17 0 0 0 0
/proc/32199/statm: 2058 1428 653 302 0 791 0
[pid=32204] ppid=32199 vsize=2572 CPUtime=0.01
/proc/32204/stat : 32204 (apt-get.sh) S 32199 32196 29493 34817 29493 4202496 404 490 0 0 0 0 0 1 22 0 1 0 75084709 2633728 273 1283457024 134512640 135304128 4288109376 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32204/statm: 643 273 232 194 0 30 0
[pid=32207] ppid=32204 vsize=52744 CPUtime=1.4
/proc/32207/stat : 32207 (apt-get) D 32204 32196 29493 34817 29493 4202496 6637 1747 350 0 103 6 27 4 18 0 1 0 75084710 54009856 6857 1283457024 134512640 134650667 4289258640 18446744073709551615 4294960130 0 0 4096 134217728 18446744071564332537 0 0 17 0 0 0 0
/proc/32207/statm: 13186 6857 6802 34 0 69 0
Current children cumulated CPU time (s) 11.57
Current children cumulated vsize (KiB) 65224

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

[startup+12.8045 s]
/proc/loadavg: 1.25 1.09 1.06 2/39 32211
/proc/meminfo: memFree=468540/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
[pid=32199] ppid=32196 vsize=8232 CPUtime=10.16
/proc/32199/stat : 32199 (apt-pbo) S 32196 32196 29493 34817 29493 4202496 1760 31101 0 0 3 2 881 130 18 0 1 0 75083679 8429568 1428 1283457024 134512640 135745756 4287701568 18446744073709551615 4294960130 0 0 135 0 18446744071564329979 0 0 17 0 0 0 0
/proc/32199/statm: 2058 1428 653 302 0 791 0
[pid=32204] ppid=32199 vsize=2572 CPUtime=0.01
/proc/32204/stat : 32204 (apt-get.sh) S 32199 32196 29493 34817 29493 4202496 404 490 0 0 0 0 0 1 22 0 1 0 75084709 2633728 273 1283457024 134512640 135304128 4288109376 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32204/statm: 643 273 232 194 0 30 0
[pid=32207] ppid=32204 vsize=52744 CPUtime=1.4
/proc/32207/stat : 32207 (apt-get) D 32204 32196 29493 34817 29493 4202496 6637 1747 350 0 103 6 27 4 18 0 1 0 75084710 54009856 6857 1283457024 134512640 134650667 4289258640 18446744073709551615 4294960130 0 0 4096 134217728 18446744071564332537 0 0 17 0 0 0 0
/proc/32207/statm: 13186 6857 6802 34 0 69 0
Current children cumulated CPU time (s) 11.57
Current children cumulated vsize (KiB) 65224

[startup+14.4103 s]
/proc/loadavg: 1.25 1.09 1.06 2/37 32215
/proc/meminfo: memFree=420500/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
[pid=32199] ppid=32196 vsize=53356 CPUtime=12.27
/proc/32199/stat : 32199 (apt-pbo) R 32196 32196 29493 34817 29493 4202496 13000 41435 0 350 57 7 1016 147 21 0 1 0 75083679 54636544 12377 1283457024 134512640 135745756 4287701568 18446744073709551615 135277595 0 0 128 0 0 0 0 17 0 0 0 0
/proc/32199/statm: 13339 12377 6766 302 0 5661 0
Current children cumulated CPU time (s) 12.27
Current children cumulated vsize (KiB) 55032

[startup+14.8104 s]
/proc/loadavg: 1.25 1.09 1.06 2/37 32215
/proc/meminfo: memFree=420500/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
[pid=32199] ppid=32196 vsize=53356 CPUtime=12.31
/proc/32199/stat : 32199 (apt-pbo) S 32196 32196 29493 34817 29493 4202496 13046 41435 0 350 60 8 1016 147 19 0 1 0 75083679 54636544 12379 1283457024 134512640 135745756 4287701568 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/32199/statm: 13339 12379 6767 302 0 5661 0
Current children cumulated CPU time (s) 12.31
Current children cumulated vsize (KiB) 55032

[startup+15.0105 s]
/proc/loadavg: 1.25 1.09 1.06 2/37 32215
/proc/meminfo: memFree=420500/1048576 swapFree=0/0
[pid=32196] ppid=32195 vsize=1676 CPUtime=0
/proc/32196/stat : 32196 (sh) S 32195 32196 29493 34817 29493 4202496 223 174 0 0 0 0 0 0 25 0 1 0 75083679 1716224 129 1283457024 134512640 134593992 4287001184 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 419 129 112 20 0 46 0
[pid=32199] ppid=32196 vsize=53356 CPUtime=12.31
/proc/32199/stat : 32199 (apt-pbo) S 32196 32196 29493 34817 29493 4202496 13046 41435 0 350 60 8 1016 147 18 0 1 0 75083679 54636544 12379 1283457024 134512640 135745756 4287701568 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/32199/statm: 13339 12379 6767 302 0 5661 0
Current children cumulated CPU time (s) 12.31
Current children cumulated vsize (KiB) 55032

Child status: 255
Real time (s): 15.089
CPU time (s): 12.9128
CPU user time (s): 11.2767
CPU system time (s): 1.6361
CPU usage (%): 85.5775
Max. virtual memory (cumulated for all children) (KiB): 132840

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.2767
system time used= 1.6361
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 63618
page faults= 350
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2294
involuntary context switches= 2294

runsolver used 0 second user time and 0.004 second system time

The end