/brz/remove-bazaar

To get this branch, use:
bzr branch http://gegoxaren.bato24.eu/bzr/brz/remove-bazaar

« back to all changes in this revision

Viewing changes to bzrlib/smart/protocol.py

  • Committer: John Arbash Meinel
  • Date: 2009-12-11 21:45:27 UTC
  • mto: (4896.1.3 2.1.0b4-dev)
  • mto: This revision was merged to the branch mainline in revision 4898.
  • Revision ID: john@arbash-meinel.com-20091211214527-7c7yzh15spl8o8d3
Make -Dhpss log debug information for the server process.

hpssdetail will dump individual chunk information, and hpss will
dump information about every request made, and the basic response info.

Show diffs side-by-side

added added

removed removed

Lines of Context:
bzrlib/smart/protocol.py
22
22
from cStringIO import StringIO
23
23
import struct
24
24
import sys
 
25
import threading
25
26
import time
26
27
 
27
28
import bzrlib
28
 
from bzrlib import debug
29
 
from bzrlib import errors
 
29
from bzrlib import (
 
30
    debug,
 
31
    errors,
 
32
    osutils,
 
33
    )
30
34
from bzrlib.smart import message, request
31
35
from bzrlib.trace import log_exception_quietly, mutter
32
36
from bzrlib.bencode import bdecode_as_tuple, bencode
615
619
            mutter('hpss call:   %s', repr(args)[1:-1])
616
620
            if getattr(self._request._medium, 'base', None) is not None:
617
621
                mutter('             (to %s)', self._request._medium.base)
618
 
            self._request_start_time = time.time()
 
622
            self._request_start_time = osutils.timer_func()
619
623
        self._write_args(args)
620
624
        self._request.finished_writing()
621
625
        self._last_verb = args[0]
630
634
            if getattr(self._request._medium, '_path', None) is not None:
631
635
                mutter('                  (to %s)', self._request._medium._path)
632
636
            mutter('              %d bytes', len(body))
633
 
            self._request_start_time = time.time()
 
637
            self._request_start_time = osutils.timer_func()
634
638
            if 'hpssdetail' in debug.debug_flags:
635
639
                mutter('hpss body content: %s', body)
636
640
        self._write_args(args)
649
653
            mutter('hpss call w/readv: %s', repr(args)[1:-1])
650
654
            if getattr(self._request._medium, '_path', None) is not None:
651
655
                mutter('                  (to %s)', self._request._medium._path)
652
 
            self._request_start_time = time.time()
 
656
            self._request_start_time = osutils.timer_func()
653
657
        self._write_args(args)
654
658
        readv_bytes = self._serialise_offsets(body)
655
659
        bytes = self._encode_bulk_data(readv_bytes)
681
685
        if 'hpss' in debug.debug_flags:
682
686
            if self._request_start_time is not None:
683
687
                mutter('   result:   %6.3fs  %s',
684
 
                       time.time() - self._request_start_time,
 
688
                       osutils.timer_func() - self._request_start_time,
685
689
                       repr(result)[1:-1])
686
690
                self._request_start_time = None
687
691
            else:
1068
1072
        self._real_write_func = write_func
1069
1073
 
1070
1074
    def _write_func(self, bytes):
 
1075
        # TODO: It is probably more appropriate to use sum(map(len, _buf))
 
1076
        #       for total number of bytes to write, rather than buffer based on
 
1077
        #       the number of write() calls
 
1078
        # TODO: Another possibility would be to turn this into an async model.
 
1079
        #       Where we let another thread know that we have some bytes if
 
1080
        #       they want it, but we don't actually block for it
 
1081
        #       Note that osutils.send_all always sends 64kB chunks anyway, so
 
1082
        #       we might just push out smaller bits at a time?
1071
1083
        self._buf.append(bytes)
1072
1084
        if len(self._buf) > 100:
1073
1085
            self.flush()
1130
1142
        _ProtocolThreeEncoder.__init__(self, write_func)
1131
1143
        self.response_sent = False
1132
1144
        self._headers = {'Software version': bzrlib.__version__}
 
1145
        if 'hpss' in debug.debug_flags:
 
1146
            import threading
 
1147
            self._thread_id = threading.currentThread().ident
 
1148
            self._response_start_time = None
 
1149
 
 
1150
    def _trace(self, action, message, extra_bytes=None, suppress_time=False):
 
1151
        if self._response_start_time is None:
 
1152
            self._response_start_time = osutils.timer_func()
 
1153
        if suppress_time:
 
1154
            t = ''
 
1155
        else:
 
1156
            t = '%5.3fs ' % (time.clock() - self._response_start_time)
 
1157
        if extra_bytes is None:
 
1158
            extra = ''
 
1159
        else:
 
1160
            extra = ' ' + repr(extra_bytes[:40])
 
1161
            if len(extra) > 33:
 
1162
                extra = extra[:29] + extra[-1] + '...'
 
1163
        mutter('%12s: [%s] %s%s%s'
 
1164
               % (action, self._thread_id, t, message, extra))
1133
1165
 
1134
1166
    def send_error(self, exception):
1135
1167
        if self.response_sent:
1141
1173
                ('UnknownMethod', exception.verb))
1142
1174
            self.send_response(failure)
1143
1175
            return
 
1176
        if 'hpss' in debug.debug_flags:
 
1177
            self._trace('error', str(exception))
1144
1178
        self.response_sent = True
1145
1179
        self._write_protocol_version()
1146
1180
        self._write_headers(self._headers)
1160
1194
            self._write_success_status()
1161
1195
        else:
1162
1196
            self._write_error_status()
 
1197
        if 'hpss' in debug.debug_flags:
 
1198
            self._trace('response', repr(response.args), suppress_time=True)
1163
1199
        self._write_structure(response.args)
1164
1200
        if response.body is not None:
1165
1201
            self._write_prefixed_body(response.body)
 
1202
            if 'hpss' in debug.debug_flags:
 
1203
                self._trace('body', '%d bytes' % (len(response.body),),
 
1204
                            response.body)
1166
1205
        elif response.body_stream is not None:
 
1206
            count = num_bytes = 0
 
1207
            first_chunk = None
1167
1208
            for exc_info, chunk in _iter_with_errors(response.body_stream):
 
1209
                count += 1
1168
1210
                if exc_info is not None:
1169
1211
                    self._write_error_status()
1170
1212
                    error_struct = request._translate_error(exc_info[1])
1175
1217
                        self._write_error_status()
1176
1218
                        self._write_structure(chunk.args)
1177
1219
                        break
 
1220
                    num_bytes += len(chunk)
 
1221
                    if first_chunk is None:
 
1222
                        first_chunk = chunk
1178
1223
                    self._write_prefixed_body(chunk)
 
1224
                    if 'hpssdetail' in debug.debug_flags:
 
1225
                        # Not worth timing separately, as _write_func is
 
1226
                        # actually buffered
 
1227
                        self._trace('body chunk',
 
1228
                                    '%d bytes' % (len(chunk),),
 
1229
                                    chunk, suppress_time=True)
 
1230
            if 'hpss' in debug.debug_flags:
 
1231
                self._trace('body', '%d bytes %d chunks' % (num_bytes, count),
 
1232
                            response.body)
1179
1233
        self._write_end()
1180
1234
 
1181
1235
 
1230
1284
 
1231
1285
    def call(self, *args):
1232
1286
        if 'hpss' in debug.debug_flags:
 
1287
            import pdb; pdb.set_trace()
1233
1288
            mutter('hpss call:   %s', repr(args)[1:-1])
1234
1289
            base = getattr(self._medium_request._medium, 'base', None)
1235
1290
            if base is not None:
1236
1291
                mutter('             (to %s)', base)
1237
 
            self._request_start_time = time.time()
 
1292
            self._request_start_time = osutils.timer_func()
1238
1293
        self._write_protocol_version()
1239
1294
        self._write_headers(self._headers)
1240
1295
        self._write_structure(args)
1252
1307
            if path is not None:
1253
1308
                mutter('                  (to %s)', path)
1254
1309
            mutter('              %d bytes', len(body))
1255
 
            self._request_start_time = time.time()
 
1310
            self._request_start_time = osutils.timer_func()
1256
1311
        self._write_protocol_version()
1257
1312
        self._write_headers(self._headers)
1258
1313
        self._write_structure(args)
1271
1326
            path = getattr(self._medium_request._medium, '_path', None)
1272
1327
            if path is not None:
1273
1328
                mutter('                  (to %s)', path)
1274
 
            self._request_start_time = time.time()
 
1329
            self._request_start_time = osutils.timer_func()
1275
1330
        self._write_protocol_version()
1276
1331
        self._write_headers(self._headers)
1277
1332
        self._write_structure(args)
1288
1343
            path = getattr(self._medium_request._medium, '_path', None)
1289
1344
            if path is not None:
1290
1345
                mutter('                  (to %s)', path)
1291
 
            self._request_start_time = time.time()
 
1346
            self._request_start_time = osutils.timer_func()
1292
1347
        self._write_protocol_version()
1293
1348
        self._write_headers(self._headers)
1294
1349
        self._write_structure(args)