1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
|
# Copyright (C) 2007 Canonical Ltd
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; either version 2 of the License, or
# (at your option) any later version.
#
# 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.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
"""Transport decorator that logs transport operations to .bzr.log."""
# see also the transportstats plugin, which gives you some summary information
# in a machine-readable dump
import StringIO
import cStringIO
import time
import types
from bzrlib.trace import mutter
from bzrlib.transport.decorator import (
TransportDecorator,
)
from bzrlib.transport.trace import (
DecoratorServer,
TransportTraceDecorator,
)
class TransportLogDecorator(TransportDecorator):
"""Decorator for Transports that logs interesting operations to .bzr.log.
In general we want to log things that usually take a network round trip
and may be slow.
Not all operations are logged yet.
"""
def __init__(self, *args, **kw):
super(TransportLogDecorator, self).__init__(*args, **kw)
def _make_hook(hookname):
def _hook(relpath, *args, **kw):
return self._log_and_call(hookname, relpath, *args, **kw)
return _hook
for methodname in (
'append_bytes',
'append_file',
'copy_to',
'delete',
'get',
'has',
'open_write_stream',
'mkdir',
'move',
'put_bytes', 'put_bytes_non_atomic', 'put_file put_file_non_atomic',
'list_dir', 'lock_read', 'lock_write',
'readv', 'rename', 'rmdir',
'stat',
'ulock',
):
setattr(self, methodname, _make_hook(methodname))
@classmethod
def _get_url_prefix(self):
return 'log+'
def iter_files_recursive(self):
# needs special handling because it does not have a relpath parameter
mutter("%s %s"
% ('iter_files_recursive', self._decorated.base))
return self._call_and_log_result('iter_files_recursive', (), {})
def _log_and_call(self, methodname, relpath, *args, **kwargs):
if kwargs:
kwargs_str = dict(kwargs)
else:
kwargs_str = ''
mutter("%s %s %s %s"
% (methodname, self._decorated.abspath(relpath),
self._shorten(self._strip_tuple_parens(args)),
kwargs_str))
return self._call_and_log_result(methodname, (relpath,) + args, kwargs)
def _call_and_log_result(self, methodname, args, kwargs):
before = time.time()
try:
result = getattr(self._decorated, methodname)(*args, **kwargs)
except Exception, e:
mutter(" --> %s" % e)
mutter(" %.03fs" % (time.time() - before))
raise
return self._show_result(before, methodname, result)
def _show_result(self, before, methodname, result):
result_len = None
if isinstance(result, types.GeneratorType):
# eagerly pull in all the contents, so that we can measure how
# long it takes to get them. this does make the behaviour a bit
# different, but we hope not noticably so
result = list(result)
if isinstance(result, (cStringIO.OutputType, StringIO.StringIO)):
val = repr(result.getvalue())
result_len = len(val)
shown_result = "%s(%s) (%d bytes)" % (result.__class__.__name__,
self._shorten(val), result_len)
elif methodname == 'readv':
num_hunks = len(result)
total_bytes = sum((len(d) for o,d in result))
shown_result = "readv response, %d hunks, %d total bytes" % (
num_hunks, total_bytes)
result_len = total_bytes
else:
shown_result = self._shorten(self._strip_tuple_parens(result))
mutter(" --> %s" % shown_result)
# XXX: the time may be wrong when e.g. a generator object is returned from
# an http readv, if the object is returned before the bulk data
# is read.
elapsed = time.time() - before
if result_len and elapsed > 0:
# this is the rate of higher-level data, not the raw network speed
mutter(" %9.03fs %8dKB/s" % (elapsed, result_len/elapsed/1024))
else:
mutter(" %9.03fs" % (elapsed))
return result
def _shorten(self, x):
if len(x) > 70:
x = x[:67] + '...'
return x
def _strip_tuple_parens(self, t):
t = repr(t)
if t[0] == '(' and t[-1] == ')':
t = t[1:-1]
return t
class LogDecoratorServer(DecoratorServer):
"""Server for testing."""
def get_decorator_class(self):
return TransportLogDecorator
def get_test_permutations():
"""Return the permutations to be used in testing."""
return [(TransportLogDecorator, LogDecoratorServer)]
|