Mercurial > hg
comparison mercurial/extensions.py @ 39511:1ab185c78cc3
extension: add a summary of total loading time per extension
Differential Revision: https://phab.mercurial-scm.org/D4513
author | Boris Feld <boris.feld@octobus.net> |
---|---|
date | Fri, 07 Sep 2018 16:51:51 -0400 |
parents | 3a86f7eb8b78 |
children | 09a37a5d8f5d |
comparison
equal
deleted
inserted
replaced
39510:340170192874 | 39511:1ab185c78cc3 |
---|---|
164 o = getattr(mod, t, None) | 164 o = getattr(mod, t, None) |
165 if o: | 165 if o: |
166 _rejectunicode(t, o._table) | 166 _rejectunicode(t, o._table) |
167 _validatecmdtable(ui, getattr(mod, 'cmdtable', {})) | 167 _validatecmdtable(ui, getattr(mod, 'cmdtable', {})) |
168 | 168 |
169 def load(ui, name, path, log=lambda *a: None): | 169 def load(ui, name, path, log=lambda *a: None, loadingtime=None): |
170 if name.startswith('hgext.') or name.startswith('hgext/'): | 170 if name.startswith('hgext.') or name.startswith('hgext/'): |
171 shortname = name[6:] | 171 shortname = name[6:] |
172 else: | 172 else: |
173 shortname = name | 173 shortname = name |
174 if shortname in _builtin: | 174 if shortname in _builtin: |
178 log(' - loading extension: %r\n', shortname) | 178 log(' - loading extension: %r\n', shortname) |
179 _extensions[shortname] = None | 179 _extensions[shortname] = None |
180 with util.timedcm('load extension %r', shortname) as stats: | 180 with util.timedcm('load extension %r', shortname) as stats: |
181 mod = _importext(name, path, bind(_reportimporterror, ui)) | 181 mod = _importext(name, path, bind(_reportimporterror, ui)) |
182 log(' > %r extension loaded in %s\n', shortname, stats) | 182 log(' > %r extension loaded in %s\n', shortname, stats) |
183 if loadingtime is not None: | |
184 loadingtime[shortname] += stats.elapsed | |
183 | 185 |
184 # Before we do anything with the extension, check against minimum stated | 186 # Before we do anything with the extension, check against minimum stated |
185 # compatibility. This gives extension authors a mechanism to have their | 187 # compatibility. This gives extension authors a mechanism to have their |
186 # extensions short circuit when loaded with a known incompatible version | 188 # extensions short circuit when loaded with a known incompatible version |
187 # of Mercurial. | 189 # of Mercurial. |
235 if ui.configbool('devel', 'debug.extensions'): | 237 if ui.configbool('devel', 'debug.extensions'): |
236 log = lambda msg, *values: ui.debug('debug.extensions: ', | 238 log = lambda msg, *values: ui.debug('debug.extensions: ', |
237 msg % values, label='debug.extensions') | 239 msg % values, label='debug.extensions') |
238 else: | 240 else: |
239 log = lambda *a, **kw: None | 241 log = lambda *a, **kw: None |
242 loadingtime = collections.defaultdict(int) | |
240 result = ui.configitems("extensions") | 243 result = ui.configitems("extensions") |
241 if whitelist is not None: | 244 if whitelist is not None: |
242 result = [(k, v) for (k, v) in result if k in whitelist] | 245 result = [(k, v) for (k, v) in result if k in whitelist] |
243 newindex = len(_order) | 246 newindex = len(_order) |
244 log('loading %sextensions\n', 'additional ' if newindex else '') | 247 log('loading %sextensions\n', 'additional ' if newindex else '') |
250 if name not in _disabledextensions: | 253 if name not in _disabledextensions: |
251 log(' - skipping disabled extension: %r\n', name) | 254 log(' - skipping disabled extension: %r\n', name) |
252 _disabledextensions[name] = path[1:] | 255 _disabledextensions[name] = path[1:] |
253 continue | 256 continue |
254 try: | 257 try: |
255 load(ui, name, path, log) | 258 load(ui, name, path, log, loadingtime) |
256 except Exception as inst: | 259 except Exception as inst: |
257 msg = stringutil.forcebytestr(inst) | 260 msg = stringutil.forcebytestr(inst) |
258 if path: | 261 if path: |
259 ui.warn(_("*** failed to import extension %s from %s: %s\n") | 262 ui.warn(_("*** failed to import extension %s from %s: %s\n") |
260 % (name, path, msg)) | 263 % (name, path, msg)) |
290 with util.timedcm('uisetup %r', name) as stats: | 293 with util.timedcm('uisetup %r', name) as stats: |
291 if not _runuisetup(name, ui): | 294 if not _runuisetup(name, ui): |
292 log(' - the %r extension uisetup failed\n', name) | 295 log(' - the %r extension uisetup failed\n', name) |
293 broken.add(name) | 296 broken.add(name) |
294 log(' > uisetup for %r took %s\n', name, stats) | 297 log(' > uisetup for %r took %s\n', name, stats) |
298 loadingtime[name] += stats.elapsed | |
295 log('> all uisetup took %s\n', alluisetupstats) | 299 log('> all uisetup took %s\n', alluisetupstats) |
296 | 300 |
297 log('- executing extsetup hooks\n') | 301 log('- executing extsetup hooks\n') |
298 with util.timedcm('all extsetup') as allextetupstats: | 302 with util.timedcm('all extsetup') as allextetupstats: |
299 for name in _order[newindex:]: | 303 for name in _order[newindex:]: |
303 with util.timedcm('extsetup %r', name) as stats: | 307 with util.timedcm('extsetup %r', name) as stats: |
304 if not _runextsetup(name, ui): | 308 if not _runextsetup(name, ui): |
305 log(' - the %r extension extsetup failed\n', name) | 309 log(' - the %r extension extsetup failed\n', name) |
306 broken.add(name) | 310 broken.add(name) |
307 log(' > extsetup for %r took %s\n', name, stats) | 311 log(' > extsetup for %r took %s\n', name, stats) |
312 loadingtime[name] += stats.elapsed | |
308 log('> all extsetup took %s\n', allextetupstats) | 313 log('> all extsetup took %s\n', allextetupstats) |
309 | 314 |
310 for name in broken: | 315 for name in broken: |
311 log(' - disabling broken %r extension\n', name) | 316 log(' - disabling broken %r extension\n', name) |
312 _extensions[name] = None | 317 _extensions[name] = None |
358 ('templatekeyword', templatekw, 'loadkeyword'), | 363 ('templatekeyword', templatekw, 'loadkeyword'), |
359 ] | 364 ] |
360 with util.timedcm('load registration objects') as stats: | 365 with util.timedcm('load registration objects') as stats: |
361 _loadextra(ui, newindex, extraloaders) | 366 _loadextra(ui, newindex, extraloaders) |
362 log('> extension registration object loading took %s\n', stats) | 367 log('> extension registration object loading took %s\n', stats) |
368 | |
369 # Report per extension loading time (except reposetup) | |
370 for name in sorted(loadingtime): | |
371 extension_msg = '> extension %s take a total of %s to load\n' | |
372 log(extension_msg, name, util.timecount(loadingtime[name])) | |
373 | |
363 log('extension loading complete\n') | 374 log('extension loading complete\n') |
364 | 375 |
365 def _loadextra(ui, newindex, extraloaders): | 376 def _loadextra(ui, newindex, extraloaders): |
366 for name in _order[newindex:]: | 377 for name in _order[newindex:]: |
367 module = _extensions[name] | 378 module = _extensions[name] |