Mercurial > public > mercurial-scm > hg

comparison mercurial/extensions.py @ 40996:6f2510b581a0

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
extensions: use ui.log() interface to provide detailed loading information The output format changes and the messages will be sent to stderr instead of stdout, but I don't think that matters.
author Yuya Nishihara <yuya@tcha.org>
date Sat, 15 Dec 2018 16:28:29 +0900
parents c93d046d4300
children 28a4fb793ba1
comparison
equal deleted inserted replaced
40995:19178aeb9b43 40996:6f2510b581a0
119 reportfunc(err, "hgext3rd.%s" % name, name) 119 reportfunc(err, "hgext3rd.%s" % name, name)
120 mod = _importh(name) 120 mod = _importh(name)
121 return mod 121 return mod
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.log 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 ui.log(b'extension', b' - could not import %s (%s): trying %s\n',
127 ui.debug('debug.extensions: - could not import %s (%s): trying %s\n' 127 failed, stringutil.forcebytestr(err), next)
128 % (failed, stringutil.forcebytestr(err), next)) 128 if ui.debugflag and ui.configbool('devel', 'debug.extensions'):
129 if ui.debugflag: 129 ui.traceback()
130 ui.traceback()
131 130
132 def _rejectunicode(name, xs): 131 def _rejectunicode(name, xs):
133 if isinstance(xs, (list, set, tuple)): 132 if isinstance(xs, (list, set, tuple)):
134 for x in xs: 133 for x in xs:
135 _rejectunicode(name, x) 134 _rejectunicode(name, x)
164 o = getattr(mod, t, None) 163 o = getattr(mod, t, None)
165 if o: 164 if o:
166 _rejectunicode(t, o._table) 165 _rejectunicode(t, o._table)
167 _validatecmdtable(ui, getattr(mod, 'cmdtable', {})) 166 _validatecmdtable(ui, getattr(mod, 'cmdtable', {}))
168 167
169 def load(ui, name, path, log=lambda *a: None, loadingtime=None): 168 def load(ui, name, path, loadingtime=None):
170 if name.startswith('hgext.') or name.startswith('hgext/'): 169 if name.startswith('hgext.') or name.startswith('hgext/'):
171 shortname = name[6:] 170 shortname = name[6:]
172 else: 171 else:
173 shortname = name 172 shortname = name
174 if shortname in _builtin: 173 if shortname in _builtin:
175 return None 174 return None
176 if shortname in _extensions: 175 if shortname in _extensions:
177 return _extensions[shortname] 176 return _extensions[shortname]
178 log(' - loading extension: %s\n', shortname) 177 ui.log(b'extension', b' - loading extension: %s\n', shortname)
179 _extensions[shortname] = None 178 _extensions[shortname] = None
180 with util.timedcm('load extension %s', shortname) as stats: 179 with util.timedcm('load extension %s', shortname) as stats:
181 mod = _importext(name, path, bind(_reportimporterror, ui)) 180 mod = _importext(name, path, bind(_reportimporterror, ui))
182 log(' > %s extension loaded in %s\n', shortname, stats) 181 ui.log(b'extension', b' > %s extension loaded in %s\n', shortname, stats)
183 if loadingtime is not None: 182 if loadingtime is not None:
184 loadingtime[shortname] += stats.elapsed 183 loadingtime[shortname] += stats.elapsed
185 184
186 # Before we do anything with the extension, check against minimum stated 185 # Before we do anything with the extension, check against minimum stated
187 # compatibility. This gives extension authors a mechanism to have their 186 # compatibility. This gives extension authors a mechanism to have their
191 if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2): 190 if minver and util.versiontuple(minver, 2) > util.versiontuple(n=2):
192 msg = _('(third party extension %s requires version %s or newer ' 191 msg = _('(third party extension %s requires version %s or newer '
193 'of Mercurial (current: %s); disabling)\n') 192 'of Mercurial (current: %s); disabling)\n')
194 ui.warn(msg % (shortname, minver, util.version())) 193 ui.warn(msg % (shortname, minver, util.version()))
195 return 194 return
196 log(' - validating extension tables: %s\n', shortname) 195 ui.log(b'extension', b' - validating extension tables: %s\n', shortname)
197 _validatetables(ui, mod) 196 _validatetables(ui, mod)
198 197
199 _extensions[shortname] = mod 198 _extensions[shortname] = mod
200 _order.append(shortname) 199 _order.append(shortname)
201 log(' - invoking registered callbacks: %s\n', shortname) 200 ui.log(b'extension', b' - invoking registered callbacks: %s\n',
201 shortname)
202 with util.timedcm('callbacks extension %s', shortname) as stats: 202 with util.timedcm('callbacks extension %s', shortname) as stats:
203 for fn in _aftercallbacks.get(shortname, []): 203 for fn in _aftercallbacks.get(shortname, []):
204 fn(loaded=True) 204 fn(loaded=True)
205 log(' > callbacks completed in %s\n', stats) 205 ui.log(b'extension', b' > callbacks completed in %s\n', stats)
206 return mod 206 return mod
207 207
208 def _runuisetup(name, ui): 208 def _runuisetup(name, ui):
209 uisetup = getattr(_extensions[name], 'uisetup', None) 209 uisetup = getattr(_extensions[name], 'uisetup', None)
210 if uisetup: 210 if uisetup:
233 ui.warn(_("*** failed to set up extension %s: %s\n") % (name, msg)) 233 ui.warn(_("*** failed to set up extension %s: %s\n") % (name, msg))
234 return False 234 return False
235 return True 235 return True
236 236
237 def loadall(ui, whitelist=None): 237 def loadall(ui, whitelist=None):
238 if ui.configbool('devel', 'debug.extensions'):
239 log = lambda msg, *values: ui.debug('debug.extensions: ',
240 msg % values, label='debug.extensions')
241 else:
242 log = lambda *a, **kw: None
243 loadingtime = collections.defaultdict(int) 238 loadingtime = collections.defaultdict(int)
244 result = ui.configitems("extensions") 239 result = ui.configitems("extensions")
245 if whitelist is not None: 240 if whitelist is not None:
246 result = [(k, v) for (k, v) in result if k in whitelist] 241 result = [(k, v) for (k, v) in result if k in whitelist]
247 newindex = len(_order) 242 newindex = len(_order)
248 log('loading %sextensions\n', 'additional ' if newindex else '') 243 ui.log(b'extension', b'loading %sextensions\n',
249 log('- processing %d entries\n', len(result)) 244 'additional ' if newindex else '')
245 ui.log(b'extension', b'- processing %d entries\n', len(result))
250 with util.timedcm('load all extensions') as stats: 246 with util.timedcm('load all extensions') as stats:
251 for (name, path) in result: 247 for (name, path) in result:
252 if path: 248 if path:
253 if path[0:1] == '!': 249 if path[0:1] == '!':
254 if name not in _disabledextensions: 250 if name not in _disabledextensions:
255 log(' - skipping disabled extension: %s\n', name) 251 ui.log(b'extension',
252 b' - skipping disabled extension: %s\n', name)
256 _disabledextensions[name] = path[1:] 253 _disabledextensions[name] = path[1:]
257 continue 254 continue
258 try: 255 try:
259 load(ui, name, path, log, loadingtime) 256 load(ui, name, path, loadingtime)
260 except Exception as inst: 257 except Exception as inst:
261 msg = stringutil.forcebytestr(inst) 258 msg = stringutil.forcebytestr(inst)
262 if path: 259 if path:
263 ui.warn(_("*** failed to import extension %s from %s: %s\n") 260 ui.warn(_("*** failed to import extension %s from %s: %s\n")
264 % (name, path, msg)) 261 % (name, path, msg))
267 % (name, msg)) 264 % (name, msg))
268 if isinstance(inst, error.Hint) and inst.hint: 265 if isinstance(inst, error.Hint) and inst.hint:
269 ui.warn(_("*** (%s)\n") % inst.hint) 266 ui.warn(_("*** (%s)\n") % inst.hint)
270 ui.traceback() 267 ui.traceback()
271 268
272 log('> loaded %d extensions, total time %s\n', 269 ui.log(b'extension', b'> loaded %d extensions, total time %s\n',
273 len(_order) - newindex, stats) 270 len(_order) - newindex, stats)
274 # list of (objname, loadermod, loadername) tuple: 271 # list of (objname, loadermod, loadername) tuple:
275 # - objname is the name of an object in extension module, 272 # - objname is the name of an object in extension module,
276 # from which extra information is loaded 273 # from which extra information is loaded
277 # - loadermod is the module where loader is placed 274 # - loadermod is the module where loader is placed
278 # - loadername is the name of the function, 275 # - loadername is the name of the function,
281 # This one is for the list of item that must be run before running any setup 278 # This one is for the list of item that must be run before running any setup
282 earlyextraloaders = [ 279 earlyextraloaders = [
283 ('configtable', configitems, 'loadconfigtable'), 280 ('configtable', configitems, 'loadconfigtable'),
284 ] 281 ]
285 282
286 log('- loading configtable attributes\n') 283 ui.log(b'extension', b'- loading configtable attributes\n')
287 _loadextra(ui, newindex, earlyextraloaders) 284 _loadextra(ui, newindex, earlyextraloaders)
288 285
289 broken = set() 286 broken = set()
290 log('- executing uisetup hooks\n') 287 ui.log(b'extension', b'- executing uisetup hooks\n')
291 with util.timedcm('all uisetup') as alluisetupstats: 288 with util.timedcm('all uisetup') as alluisetupstats:
292 for name in _order[newindex:]: 289 for name in _order[newindex:]:
293 log(' - running uisetup for %s\n', name) 290 ui.log(b'extension', b' - running uisetup for %s\n', name)
294 with util.timedcm('uisetup %s', name) as stats: 291 with util.timedcm('uisetup %s', name) as stats:
295 if not _runuisetup(name, ui): 292 if not _runuisetup(name, ui):
296 log(' - the %s extension uisetup failed\n', name) 293 ui.log(b'extension',
294 b' - the %s extension uisetup failed\n', name)
297 broken.add(name) 295 broken.add(name)
298 log(' > uisetup for %s took %s\n', name, stats) 296 ui.log(b'extension', b' > uisetup for %s took %s\n', name, stats)
299 loadingtime[name] += stats.elapsed 297 loadingtime[name] += stats.elapsed
300 log('> all uisetup took %s\n', alluisetupstats) 298 ui.log(b'extension', b'> all uisetup took %s\n', alluisetupstats)
301 299
302 log('- executing extsetup hooks\n') 300 ui.log(b'extension', b'- executing extsetup hooks\n')
303 with util.timedcm('all extsetup') as allextetupstats: 301 with util.timedcm('all extsetup') as allextetupstats:
304 for name in _order[newindex:]: 302 for name in _order[newindex:]:
305 if name in broken: 303 if name in broken:
306 continue 304 continue
307 log(' - running extsetup for %s\n', name) 305 ui.log(b'extension', b' - running extsetup for %s\n', name)
308 with util.timedcm('extsetup %s', name) as stats: 306 with util.timedcm('extsetup %s', name) as stats:
309 if not _runextsetup(name, ui): 307 if not _runextsetup(name, ui):
310 log(' - the %s extension extsetup failed\n', name) 308 ui.log(b'extension',
309 b' - the %s extension extsetup failed\n', name)
311 broken.add(name) 310 broken.add(name)
312 log(' > extsetup for %s took %s\n', name, stats) 311 ui.log(b'extension', b' > extsetup for %s took %s\n', name, stats)
313 loadingtime[name] += stats.elapsed 312 loadingtime[name] += stats.elapsed
314 log('> all extsetup took %s\n', allextetupstats) 313 ui.log(b'extension', b'> all extsetup took %s\n', allextetupstats)
315 314
316 for name in broken: 315 for name in broken:
317 log(' - disabling broken %s extension\n', name) 316 ui.log(b'extension', b' - disabling broken %s extension\n', name)
318 _extensions[name] = None 317 _extensions[name] = None
319 318
320 # Call aftercallbacks that were never met. 319 # Call aftercallbacks that were never met.
321 log('- executing remaining aftercallbacks\n') 320 ui.log(b'extension', b'- executing remaining aftercallbacks\n')
322 with util.timedcm('aftercallbacks') as stats: 321 with util.timedcm('aftercallbacks') as stats:
323 for shortname in _aftercallbacks: 322 for shortname in _aftercallbacks:
324 if shortname in _extensions: 323 if shortname in _extensions:
325 continue 324 continue
326 325
327 for fn in _aftercallbacks[shortname]: 326 for fn in _aftercallbacks[shortname]:
328 log(' - extension %s not loaded, notify callbacks\n', 327 ui.log(b'extension',
329 shortname) 328 b' - extension %s not loaded, notify callbacks\n',
329 shortname)
330 fn(loaded=False) 330 fn(loaded=False)
331 log('> remaining aftercallbacks completed in %s\n', stats) 331 ui.log(b'extension', b'> remaining aftercallbacks completed in %s\n', stats)
332 332
333 # loadall() is called multiple times and lingering _aftercallbacks 333 # loadall() is called multiple times and lingering _aftercallbacks
334 # entries could result in double execution. See issue4646. 334 # entries could result in double execution. See issue4646.
335 _aftercallbacks.clear() 335 _aftercallbacks.clear()
336 336
350 # - objname is the name of an object in extension module, 350 # - objname is the name of an object in extension module,
351 # from which extra information is loaded 351 # from which extra information is loaded
352 # - loadermod is the module where loader is placed 352 # - loadermod is the module where loader is placed
353 # - loadername is the name of the function, 353 # - loadername is the name of the function,
354 # which takes (ui, extensionname, extraobj) arguments 354 # which takes (ui, extensionname, extraobj) arguments
355 log('- loading extension registration objects\n') 355 ui.log(b'extension', b'- loading extension registration objects\n')
356 extraloaders = [ 356 extraloaders = [
357 ('cmdtable', commands, 'loadcmdtable'), 357 ('cmdtable', commands, 'loadcmdtable'),
358 ('colortable', color, 'loadcolortable'), 358 ('colortable', color, 'loadcolortable'),
359 ('filesetpredicate', fileset, 'loadpredicate'), 359 ('filesetpredicate', fileset, 'loadpredicate'),
360 ('internalmerge', filemerge, 'loadinternalmerge'), 360 ('internalmerge', filemerge, 'loadinternalmerge'),
363 ('templatefunc', templatefuncs, 'loadfunction'), 363 ('templatefunc', templatefuncs, 'loadfunction'),
364 ('templatekeyword', templatekw, 'loadkeyword'), 364 ('templatekeyword', templatekw, 'loadkeyword'),
365 ] 365 ]
366 with util.timedcm('load registration objects') as stats: 366 with util.timedcm('load registration objects') as stats:
367 _loadextra(ui, newindex, extraloaders) 367 _loadextra(ui, newindex, extraloaders)
368 log('> extension registration object loading took %s\n', stats) 368 ui.log(b'extension', b'> extension registration object loading took %s\n',
369 stats)
369 370
370 # Report per extension loading time (except reposetup) 371 # Report per extension loading time (except reposetup)
371 for name in sorted(loadingtime): 372 for name in sorted(loadingtime):
372 extension_msg = '> extension %s take a total of %s to load\n' 373 ui.log(b'extension', b'> extension %s take a total of %s to load\n',
373 log(extension_msg, name, util.timecount(loadingtime[name])) 374 name, util.timecount(loadingtime[name]))
374 375
375 log('extension loading complete\n') 376 ui.log(b'extension', b'extension loading complete\n')
376 377
377 def _loadextra(ui, newindex, extraloaders): 378 def _loadextra(ui, newindex, extraloaders):
378 for name in _order[newindex:]: 379 for name in _order[newindex:]:
379 module = _extensions[name] 380 module = _extensions[name]
380 if not module: 381 if not module: