Mercurial > public > mercurial-scm > hg-stable

comparison mercurial/extensions.py @ 38838:d58958676b3c

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
extensions: add detailed loading information This lets you track down what exactly is happening during extension loading, and how long various steps took.
author Martijn Pieters <mj@zopatista.com>
date Wed, 01 Aug 2018 16:06:53 +0200
parents fcb517ff9562
children 331ab85e910b
comparison
equal deleted inserted replaced
38837:8751d1e2a7ff 38838:d58958676b3c
122 122
123 def _reportimporterror(ui, err, failed, next): 123 def _reportimporterror(ui, err, failed, next):
124 # note: this ui.debug happens before --debug is processed, 124 # note: this ui.debug happens before --debug is processed,
125 # Use --config ui.debug=1 to see them. 125 # Use --config ui.debug=1 to see them.
126 if ui.configbool('devel', 'debug.extensions'): 126 if ui.configbool('devel', 'debug.extensions'):
127 ui.debug('could not import %s (%s): trying %s\n' 127 ui.debug('debug.extensions: - could not import %s (%s): trying %s\n'
128 % (failed, stringutil.forcebytestr(err), next)) 128 % (failed, stringutil.forcebytestr(err), next))
129 if ui.debugflag: 129 if ui.debugflag:
130 ui.traceback() 130 ui.traceback()
131 131
132 def _rejectunicode(name, xs): 132 def _rejectunicode(name, xs):
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): 169 def load(ui, name, path, log=lambda *a: 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:
175 return None 175 return None
176 if shortname in _extensions: 176 if shortname in _extensions:
177 return _extensions[shortname] 177 return _extensions[shortname]
178 log(' - loading extension: %r\n', shortname)
178 _extensions[shortname] = None 179 _extensions[shortname] = None
179 mod = _importext(name, path, bind(_reportimporterror, ui)) 180 with util.timedcm() as stats:
181 mod = _importext(name, path, bind(_reportimporterror, ui))
182 log(' > %r extension loaded in %s\n', shortname, stats)
180 183
181 # Before we do anything with the extension, check against minimum stated 184 # Before we do anything with the extension, check against minimum stated
182 # compatibility. This gives extension authors a mechanism to have their 185 # compatibility. This gives extension authors a mechanism to have their
183 # extensions short circuit when loaded with a known incompatible version 186 # extensions short circuit when loaded with a known incompatible version
184 # of Mercurial. 187 # of Mercurial.
185 minver = getattr(mod, 'minimumhgversion', None) 188 minver = getattr(mod, 'minimumhgversion', None)
186 if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2): 189 if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2):
187 ui.warn(_('(third party extension %s requires version %s or newer ' 190 ui.warn(_('(third party extension %s requires version %s or newer '
188 'of Mercurial; disabling)\n') % (shortname, minver)) 191 'of Mercurial; disabling)\n') % (shortname, minver))
189 return 192 return
193 log(' - validating extension tables: %r\n', shortname)
190 _validatetables(ui, mod) 194 _validatetables(ui, mod)
191 195
192 _extensions[shortname] = mod 196 _extensions[shortname] = mod
193 _order.append(shortname) 197 _order.append(shortname)
194 for fn in _aftercallbacks.get(shortname, []): 198 log(' - invoking registered callbacks: %r\n', shortname)
195 fn(loaded=True) 199 with util.timedcm() as stats:
200 for fn in _aftercallbacks.get(shortname, []):
201 fn(loaded=True)
202 log(' > callbacks completed in %s\n', stats)
196 return mod 203 return mod
197 204
198 def _runuisetup(name, ui): 205 def _runuisetup(name, ui):
199 uisetup = getattr(_extensions[name], 'uisetup', None) 206 uisetup = getattr(_extensions[name], 'uisetup', None)
200 if uisetup: 207 if uisetup:
223 ui.warn(_("*** failed to set up extension %s: %s\n") % (name, msg)) 230 ui.warn(_("*** failed to set up extension %s: %s\n") % (name, msg))
224 return False 231 return False
225 return True 232 return True
226 233
227 def loadall(ui, whitelist=None): 234 def loadall(ui, whitelist=None):
235 if ui.configbool('devel', 'debug.extensions'):
236 log = lambda msg, *values: ui.debug('debug.extensions: ',
237 msg % values, label='debug.extensions')
238 else:
239 log = lambda *a, **kw: None
228 result = ui.configitems("extensions") 240 result = ui.configitems("extensions")
229 if whitelist is not None: 241 if whitelist is not None:
230 result = [(k, v) for (k, v) in result if k in whitelist] 242 result = [(k, v) for (k, v) in result if k in whitelist]
231 newindex = len(_order) 243 newindex = len(_order)
232 for (name, path) in result: 244 log('loading %sextensions\n', 'additional ' if newindex else '')
233 if path: 245 log('- processing %d entries\n', len(result))
234 if path[0:1] == '!': 246 with util.timedcm() as stats:
235 _disabledextensions[name] = path[1:] 247 for (name, path) in result:
236 continue
237 try:
238 load(ui, name, path)
239 except Exception as inst:
240 msg = stringutil.forcebytestr(inst)
241 if path: 248 if path:
242 ui.warn(_("*** failed to import extension %s from %s: %s\n") 249 if path[0:1] == '!':
243 % (name, path, msg)) 250 if name not in _disabledextensions:
244 else: 251 log(' - skipping disabled extension: %r\n', name)
245 ui.warn(_("*** failed to import extension %s: %s\n") 252 _disabledextensions[name] = path[1:]
246 % (name, msg)) 253 continue
247 if isinstance(inst, error.Hint) and inst.hint: 254 try:
248 ui.warn(_("*** (%s)\n") % inst.hint) 255 load(ui, name, path, log)
249 ui.traceback() 256 except Exception as inst:
257 msg = stringutil.forcebytestr(inst)
258 if path:
259 ui.warn(_("*** failed to import extension %s from %s: %s\n")
260 % (name, path, msg))
261 else:
262 ui.warn(_("*** failed to import extension %s: %s\n")
263 % (name, msg))
264 if isinstance(inst, error.Hint) and inst.hint:
265 ui.warn(_("*** (%s)\n") % inst.hint)
266 ui.traceback()
267
268 log('> loaded %d extensions, total time %s\n',
269 len(_order) - newindex, stats)
250 # list of (objname, loadermod, loadername) tuple: 270 # list of (objname, loadermod, loadername) tuple:
251 # - objname is the name of an object in extension module, 271 # - objname is the name of an object in extension module,
252 # from which extra information is loaded 272 # from which extra information is loaded
253 # - loadermod is the module where loader is placed 273 # - loadermod is the module where loader is placed
254 # - loadername is the name of the function, 274 # - loadername is the name of the function,
256 # 276 #
257 # This one is for the list of item that must be run before running any setup 277 # This one is for the list of item that must be run before running any setup
258 earlyextraloaders = [ 278 earlyextraloaders = [
259 ('configtable', configitems, 'loadconfigtable'), 279 ('configtable', configitems, 'loadconfigtable'),
260 ] 280 ]
281
282 log('- loading configtable attributes\n')
261 _loadextra(ui, newindex, earlyextraloaders) 283 _loadextra(ui, newindex, earlyextraloaders)
262 284
263 broken = set() 285 broken = set()
286 log('- executing uisetup hooks\n')
264 for name in _order[newindex:]: 287 for name in _order[newindex:]:
265 if not _runuisetup(name, ui): 288 log(' - running uisetup for %r\n', name)
266 broken.add(name) 289 with util.timedcm() as stats:
267 290 if not _runuisetup(name, ui):
291 log(' - the %r extension uisetup failed\n', name)
292 broken.add(name)
293 log(' > uisetup for %r took %s\n', name, stats)
294
295 log('- executing extsetup hooks\n')
268 for name in _order[newindex:]: 296 for name in _order[newindex:]:
269 if name in broken: 297 if name in broken:
270 continue 298 continue
271 if not _runextsetup(name, ui): 299 log(' - running extsetup for %r\n', name)
272 broken.add(name) 300 with util.timedcm() as stats:
301 if not _runextsetup(name, ui):
302 log(' - the %r extension extsetup failed\n', name)
303 broken.add(name)
304 log(' > extsetup for %r took %s\n', name, stats)
273 305
274 for name in broken: 306 for name in broken:
307 log(' - disabling broken %r extension\n', name)
275 _extensions[name] = None 308 _extensions[name] = None
276 309
277 # Call aftercallbacks that were never met. 310 # Call aftercallbacks that were never met.
278 for shortname in _aftercallbacks: 311 log('- executing remaining aftercallbacks\n')
279 if shortname in _extensions: 312 with util.timedcm() as stats:
280 continue 313 for shortname in _aftercallbacks:
281 314 if shortname in _extensions:
282 for fn in _aftercallbacks[shortname]: 315 continue
283 fn(loaded=False) 316
317 for fn in _aftercallbacks[shortname]:
318 log(' - extension %r not loaded, notify callbacks\n',
319 shortname)
320 fn(loaded=False)
321 log('> remaining aftercallbacks completed in %s\n', stats)
284 322
285 # loadall() is called multiple times and lingering _aftercallbacks 323 # loadall() is called multiple times and lingering _aftercallbacks
286 # entries could result in double execution. See issue4646. 324 # entries could result in double execution. See issue4646.
287 _aftercallbacks.clear() 325 _aftercallbacks.clear()
288 326
302 # - objname is the name of an object in extension module, 340 # - objname is the name of an object in extension module,
303 # from which extra information is loaded 341 # from which extra information is loaded
304 # - loadermod is the module where loader is placed 342 # - loadermod is the module where loader is placed
305 # - loadername is the name of the function, 343 # - loadername is the name of the function,
306 # which takes (ui, extensionname, extraobj) arguments 344 # which takes (ui, extensionname, extraobj) arguments
345 log('- loading extension registration objects\n')
307 extraloaders = [ 346 extraloaders = [
308 ('cmdtable', commands, 'loadcmdtable'), 347 ('cmdtable', commands, 'loadcmdtable'),
309 ('colortable', color, 'loadcolortable'), 348 ('colortable', color, 'loadcolortable'),
310 ('filesetpredicate', fileset, 'loadpredicate'), 349 ('filesetpredicate', fileset, 'loadpredicate'),
311 ('internalmerge', filemerge, 'loadinternalmerge'), 350 ('internalmerge', filemerge, 'loadinternalmerge'),
312 ('revsetpredicate', revset, 'loadpredicate'), 351 ('revsetpredicate', revset, 'loadpredicate'),
313 ('templatefilter', templatefilters, 'loadfilter'), 352 ('templatefilter', templatefilters, 'loadfilter'),
314 ('templatefunc', templatefuncs, 'loadfunction'), 353 ('templatefunc', templatefuncs, 'loadfunction'),
315 ('templatekeyword', templatekw, 'loadkeyword'), 354 ('templatekeyword', templatekw, 'loadkeyword'),
316 ] 355 ]
317 _loadextra(ui, newindex, extraloaders) 356 with util.timedcm() as stats:
357 _loadextra(ui, newindex, extraloaders)
358 log('> extension registration object loading took %s\n', stats)
359 log('extension loading complete\n')
318 360
319 def _loadextra(ui, newindex, extraloaders): 361 def _loadextra(ui, newindex, extraloaders):
320 for name in _order[newindex:]: 362 for name in _order[newindex:]:
321 module = _extensions[name] 363 module = _extensions[name]
322 if not module: 364 if not module: