From bed07479f1b4bf24a0b9c84217d41ebbe880a8fb Mon Sep 17 00:00:00 2001 From: tassaron Date: Mon, 14 Aug 2017 10:10:32 -0400 Subject: [PATCH] faster Spectrum preview & custom VERBOSE loglvl --- src/__init__.py | 23 +++++++++++++++++ src/component.py | 5 ++++ src/components/spectrum.py | 52 +++++++++++++++++++------------------- src/core.py | 10 +++++--- src/mainwindow.py | 6 ++--- src/toolkit/frame.py | 3 ++- src/video_thread.py | 4 +-- 7 files changed, 67 insertions(+), 36 deletions(-) diff --git a/src/__init__.py b/src/__init__.py index 2f4cffa..73f174a 100644 --- a/src/__init__.py +++ b/src/__init__.py @@ -1,5 +1,28 @@ import sys import os +import logging + + +class Logger(logging.getLoggerClass()): + ''' + Custom Logger class to handle custom VERBOSE log level. + Levels used in this program are as follows: + VERBOSE Annoyingly frequent debug messages (e.g, in loops) + DEBUG Ordinary debug information + INFO Expected events that are expensive or irreversible + WARNING A non-fatal error or suspicious behaviour + ERROR Any error that would interrupt the user + CRITICAL Things that really shouldn't happen at all + ''' + def __init__(self, name, level=logging.NOTSET): + super().__init__(name, level) + logging.addLevelName(5, "VERBOSE") + + def verbose(self, msg, *args, **kwargs): + if self.isEnabledFor(5): + self._log(5, msg, args, **kwargs) +logging.setLoggerClass(Logger) +logging.VERBOSE = 5 if getattr(sys, 'frozen', False): diff --git a/src/component.py b/src/component.py index d011f1e..cf3085c 100644 --- a/src/component.py +++ b/src/component.py @@ -39,6 +39,11 @@ class ComponentMetaclass(type(QtCore.QObject)): def renderWrapper(func): def renderWrapper(self, *args, **kwargs): try: + log.verbose('### %s #%s renders%s frame %s###' % ( + self.__class__.name, str(self.compPos), + '' if args else ' a preview', + '' if not args else '%s ' % args[0], + )) return func(self, *args, **kwargs) except Exception as e: try: diff --git a/src/components/spectrum.py b/src/components/spectrum.py index 32763c0..246b839 100644 --- a/src/components/spectrum.py +++ b/src/components/spectrum.py @@ -27,6 +27,8 @@ class Component(Component): self._image = BlankFrame(self.width, self.height) self.chunkSize = 4 * self.width * self.height self.changedOptions = True + self.previewSize = (214, 120) + self.previewPipe = None if hasattr(self.parent, 'window'): # update preview when audio file changes (if genericPreview is off) @@ -72,7 +74,8 @@ class Component(Component): if not changedSize \ and not self.changedOptions \ and self.previewFrame is not None: - log.debug('Comp #%s is reusing old preview frame' % self.compPos) + log.debug( + 'Spectrum #%s is reusing old preview frame' % self.compPos) return self.previewFrame frame = self.getPreviewFrame() @@ -86,6 +89,7 @@ class Component(Component): def preFrameRender(self, **kwargs): super().preFrameRender(**kwargs) + self.previewPipe.wait() self.updateChunksize() w, h = scale(self.scale, self.width, self.height, str) self.video = FfmpegVideo( @@ -141,18 +145,21 @@ class Component(Component): with open(logFilename, 'w') as logf: logf.write(" ".join(command) + '\n\n') with open(logFilename, 'a') as logf: - pipe = openPipe( + self.previewPipe = openPipe( command, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=logf, bufsize=10**8 ) - byteFrame = pipe.stdout.read(self.chunkSize) - closePipe(pipe) + byteFrame = self.previewPipe.stdout.read(self.chunkSize) + closePipe(self.previewPipe) frame = self.finalizeFrame(byteFrame) return frame def makeFfmpegFilter(self, preview=False, startPt=0): - w, h = scale(self.scale, self.width, self.height, str) + if preview: + w, h = self.previewSize + else: + w, h = (self.width, self.height) color = self.page.comboBox_color.currentText().lower() genericPreview = self.settings.value("pref_genericPreview") @@ -173,8 +180,7 @@ class Component(Component): 'showspectrum=s=%sx%s:slide=scroll:win_func=%s:' 'color=%s:scale=%s,' 'colorkey=color=black:similarity=0.1:blend=0.5' % ( - self.settings.value("outputWidth"), - self.settings.value("outputHeight"), + w, h, self.page.comboBox_window.currentText(), color, amplitude, ) @@ -197,8 +203,7 @@ class Component(Component): filter_ = ( 'ahistogram=r=%s:s=%sx%s:dmode=separate:ascale=%s:scale=%s' % ( self.settings.value("outputFrameRate"), - self.settings.value("outputWidth"), - self.settings.value("outputHeight"), + w, h, amplitude, display ) ) @@ -214,8 +219,7 @@ class Component(Component): m = self.page.comboBox_mode.currentText() filter_ = ( 'avectorscope=s=%sx%s:draw=%s:m=%s:scale=%s:zoom=%s' % ( - self.settings.value("outputWidth"), - self.settings.value("outputHeight"), + w, h, 'line'if self.draw else 'dot', m, amplitude, str(self.zoom), ) @@ -225,8 +229,7 @@ class Component(Component): 'showcqt=r=%s:s=%sx%s:count=30:text=0:tc=%s,' 'colorkey=color=black:similarity=0.1:blend=0.5 ' % ( self.settings.value("outputFrameRate"), - self.settings.value("outputWidth"), - self.settings.value("outputHeight"), + w, h, str(self.tc), ) ) @@ -235,28 +238,28 @@ class Component(Component): 'aphasemeter=r=%s:s=%sx%s:video=1 [atrash][vtmp1]; ' '[atrash] anullsink; ' '[vtmp1] colorkey=color=black:similarity=0.1:blend=0.5, ' - 'crop=in_w/8:in_h:(in_w/8)*7:0 '% ( + 'crop=in_w/8:in_h:(in_w/8)*7:0 ' % ( self.settings.value("outputFrameRate"), - self.settings.value("outputWidth"), - self.settings.value("outputHeight"), + w, h, ) ) return [ '-filter_complex', '%s%s%s%s [v1]; ' - '[v1] %sscale=%s:%s%s%s%s [v]' % ( + '[v1] %s%s%s%s%s [v]' % ( exampleSound() if preview and genericPreview else '[0:a] ', 'compand=gain=4,' if self.compress else '', 'aformat=channel_layouts=mono,' if self.mono else '', filter_, 'hflip, ' if self.mirror else '', - w, h, - ', hue=h=%s:s=10' % str(self.hue) if self.hue > 0 else '', - ', trim=start=%s:end=%s' % ( + 'trim=start=%s:end=%s, ' % ( "{0:.3f}".format(startPt + 12), "{0:.3f}".format(startPt + 12.5) ) if preview else '', + 'scale=%sx%s' % scale( + self.scale, self.width, self.height, str), + ', hue=h=%s:s=10' % str(self.hue) if self.hue > 0 else '', ', convolution=-2 -1 0 -1 1 1 0 1 2:-2 -1 0 -1 1 1 0 1 2:-2 ' '-1 0 -1 1 1 0 1 2:-2 -1 0 -1 1 1 0 1 2' if self.filterType == 3 else '' @@ -281,10 +284,7 @@ class Component(Component): self._image = image except ValueError: image = self._image - if self.scale != 100 \ - or self.x != 0 or self.y != 0: - frame = BlankFrame(self.width, self.height) - frame.paste(image, box=(self.x, self.y)) - else: - frame = image + + frame = BlankFrame(self.width, self.height) + frame.paste(image, box=(self.x, self.y)) return frame diff --git a/src/core.py b/src/core.py index 2b85f7e..4dfb210 100644 --- a/src/core.py +++ b/src/core.py @@ -562,9 +562,10 @@ class Core: logStream = logging.StreamHandler() logStream.setLevel(STDOUT_LOGLVL) - # create formatters and put everything together + # create formatters for each stream fileFormatter = logging.Formatter( - '[%(asctime)s] <%(name)s> %(levelname)s: %(message)s' + '[%(asctime)s] %(threadName)-10.10s %(name)-23.23s %(levelname)s: ' + '%(message)s' ) streamFormatter = logging.Formatter( '<%(name)s> %(message)s' @@ -572,13 +573,14 @@ class Core: logFile.setFormatter(fileFormatter) libLogFile.setFormatter(fileFormatter) logStream.setFormatter(streamFormatter) + log = logging.getLogger('AVP') - log.setLevel(FILE_LOGLVL) log.addHandler(logFile) log.addHandler(logStream) libLog = logging.getLogger() - libLog.setLevel(FILE_LOGLVL) libLog.addHandler(libLogFile) + # lowest level must be explicitly set on the root Logger + libLog.setLevel(0) # always store settings in class variables even if a Core object is not created Core.storeSettings() diff --git a/src/mainwindow.py b/src/mainwindow.py index 1abb108..af6e190 100644 --- a/src/mainwindow.py +++ b/src/mainwindow.py @@ -44,7 +44,7 @@ class MainWindow(QtWidgets.QMainWindow): self.window = window self.core = Core() log.debug( - 'Main thread id: {}'.format(QtCore.QThread.currentThreadId())) + 'Main thread id: {}'.format(int(QtCore.QThread.currentThreadId()))) # widgets of component settings self.pages = [] @@ -465,8 +465,8 @@ class MainWindow(QtWidgets.QMainWindow): and filecmp.cmp( self.autosavePath, self.currentProject) == identical: log.debug( - 'Autosave found %s to be identical' % \ - 'not' if not identical else '' + 'Autosave found %s to be identical' + % 'not' if not identical else '' ) return True except FileNotFoundError: diff --git a/src/toolkit/frame.py b/src/toolkit/frame.py index 63774a6..ad8537c 100644 --- a/src/toolkit/frame.py +++ b/src/toolkit/frame.py @@ -21,6 +21,7 @@ class FramePainter(QtGui.QPainter): Pillow image with finalize() ''' def __init__(self, width, height): + log.verbose('Creating new FramePainter') image = BlankFrame(width, height) self.image = QtGui.QImage(ImageQt(image)) super().__init__(self.image) @@ -77,7 +78,7 @@ def defaultSize(framefunc): def FloodFrame(width, height, RgbaTuple): - log.debug('Creating new %s*%s %s flood frame' % ( + log.verbose('Creating new %s*%s %s flood frame' % ( width, height, RgbaTuple)) return Image.new("RGBA", (width, height), RgbaTuple) diff --git a/src/video_thread.py b/src/video_thread.py index 5acbda4..87fb9bd 100644 --- a/src/video_thread.py +++ b/src/video_thread.py @@ -212,7 +212,7 @@ class Worker(QtCore.QObject): compError[0] ) ) - log.critical(errMsg) + log.error(errMsg) comp._error.emit(errMsg, compError[1]) break if 'static' in compProps: @@ -221,7 +221,7 @@ class Worker(QtCore.QObject): if self.canceled: if canceledByComponent: - log.critical('Export cancelled by component #%s (%s): %s' % ( + log.error('Export cancelled by component #%s (%s): %s' % ( compNo, comp.name, 'No message.' if comp.error() is None else (