From fc40190c29fb2b459002b12039262e112d395dfe Mon Sep 17 00:00:00 2001 From: Piotr Sarnacki Date: Sat, 3 Nov 2012 18:30:03 +0100 Subject: [PATCH] Optimize log viewer Till now, log viewer was rendered in handlebars, which was the simplest solution, but it had a major drawback - every append to log caused it to rerender which was not efficient and memory consuming. The new approach is to make Travis.Log interpret the log and send lines with instructions to the view, so for example if view should add a line, it gets something like: { number: 1, content: '$ bundle install' } Such approach is required to handle cases where data coming from pusher is not actually a new line. For example output containing dots from tests needs to be appended: $ rake .... Such output could be sent to client in 2 chunks: "$ rake\n.." and "..". In such situation we would need to send 3 instructions: { number: 1, content: '$ rake' } { number: 2, content: '..' } { number: 2, content: '..', append: true } The third instruction can come much later, because tests can take a while to run, so we can't assume that each line will come in one piece. The other scenario is \r, for example when showing progress: \rDownloading: 10% \rDownloading: 50% \rDownloading: 100% Such input should be changed into such instructions: { number: 1, content: 'Downloading: 10%' } { number: 1, content: 'Downloading: 50%', replace: true } { number: 1, content: 'Downloading: 100%', replace: true } Travis.Log also supports folds, for example on bundle install, the code was rewritten to make folds management simpler. --- Assetfile | 2 +- assets/scripts/app/models/artifact.coffee | 11 +- assets/scripts/app/templates/jobs/log.hbs | 16 +- assets/scripts/app/views/job.coffee | 89 ++++++- assets/scripts/lib/travis/log.coffee | 146 +++++++---- assets/scripts/spec/unit/artifact_spec.coffee | 36 +++ assets/scripts/spec/unit/log_spec.coffee | 232 ++++++++++++++++++ .../spec/unit/views/log_view_spec.coffee | 74 ++++++ assets/styles/main/log.sass | 4 + 9 files changed, 557 insertions(+), 53 deletions(-) create mode 100644 assets/scripts/spec/unit/artifact_spec.coffee create mode 100644 assets/scripts/spec/unit/log_spec.coffee create mode 100644 assets/scripts/spec/unit/views/log_view_spec.coffee diff --git a/Assetfile b/Assetfile index 39c133e8..819e78ce 100644 --- a/Assetfile +++ b/Assetfile @@ -34,7 +34,7 @@ input assets.scripts do safe_concat assets.vendor_order, 'vendor.js' end - match '{spec,spec/unit}/*.js' do + match '{spec,spec/unit,spec/unit/views}/*.js' do concat 'spec/specs.js' end diff --git a/assets/scripts/app/models/artifact.coffee b/assets/scripts/app/models/artifact.coffee index 8855496d..bb16efcb 100644 --- a/assets/scripts/app/models/artifact.coffee +++ b/assets/scripts/app/models/artifact.coffee @@ -5,6 +5,7 @@ require 'travis/model' init: -> @_super.apply this, arguments @set 'queue', Ember.A([]) + @set 'parts', Ember.ArrayProxy.create(content: []) @addObserver 'body', @fetchWorker @fetchWorker() @@ -13,20 +14,26 @@ require 'travis/model' @set('body', '') append: (body) -> - if @get('isLoaded') + if @get('isInitialized') + @get('parts').pushObject body @set('body', @get('body') + body) else @get('queue').pushObject(body) recordDidLoad: (-> if @get('isLoaded') + if (body = @get 'body') && @get('parts.length') == 0 + @get('parts').pushObject body + + @set 'isInitialized', true + queue = @get('queue') if queue.get('length') > 0 @append queue.toArray().join('') ).observes('isLoaded') fetchWorker: -> - if body = @get('body') + if !@get('workerName') && (body = @get('body')) line = body.split("\n")[0] if line && (match = line.match /Using worker: (.*)/) if worker = match[1] diff --git a/assets/scripts/app/templates/jobs/log.hbs b/assets/scripts/app/templates/jobs/log.hbs index fb563dc6..b0f49128 100644 --- a/assets/scripts/app/templates/jobs/log.hbs +++ b/assets/scripts/app/templates/jobs/log.hbs @@ -1,10 +1,18 @@ {{view.logSubscriber}} {{#if view.job.log.isLoaded}} - 

-    
-    
-  {{{formatLog log.body repo="repository" item="parentView.currentItem"}}}
+ {{! this #with + #if is needed because I want to rerender 'pre' when log changes to properly clean it up, + this should probably be refactored to use container view}} + {{#with view.job.log}} + {{#if id}} + {{#view view.PreView logBinding="view.context.log" logUrlBinding="view.logUrl"}} + 

+          
+          
+
+ {{/view}} + {{/if}} + {{/with}} {{#if sponsor.name}}

%@%@

'.fmt(pathWithNumber, number, number, number, line) + + if payload.fold && !payload.foldContinuation + line = "
#{line}
" + + if payload.replace + this.$("#log #L#{number}").parent().replaceWith line + else if payload.append + this.$("#log #L#{number}").parent().append line + else if payload.foldContinuation + this.$("#log .fold.#{payload.fold}:last").append line + else + this.$('#log').append(line) + + if payload.foldEnd + this.$("#log .fold.#{payload.fold}:last").removeClass('show-first-line') + diff --git a/assets/scripts/lib/travis/log.coffee b/assets/scripts/lib/travis/log.coffee index 46c7fab2..6cb8b29a 100644 --- a/assets/scripts/lib/travis/log.coffee +++ b/assets/scripts/lib/travis/log.coffee @@ -1,41 +1,111 @@ -@Travis.Log = - FOLDS: - schema: /(\$ (?:bundle exec )?rake( db:create)? db:schema:load[\s\S]*?-- assume_migrated_upto_version[\s\S]*?<\/p>\n.*<\/p>)/g - migrate: /(\$ (?:bundle exec )?rake( db:create)? db:migrate[\s\S]*== +\w+: migrated \(.*\) =+)/g - bundle: /(\$ bundle install.*<\/p>\n((Updating|Using|Installing|Fetching|remote:|Receiving|Resolving).*?<\/p>\n|<\/p>\n)*)/g - exec: /([\/\w]*.rvm\/rubies\/[\S]*?\/(ruby|rbx|jruby) .*?<\/p>)/g +# TODO: revisit those patterns +FOLDS = [ + Em.Object.create(name: 'schema', startPattern: /^\$ (?:bundle exec )?rake( db:create)? db:schema:load/, endPattern: /^\$/) + Em.Object.create(name: 'migrate', startPattern: /^\$ (?:bundle exec )?rake( db:create)? db:migrate/, endPattern: /^\$/) + Em.Object.create(name: 'bundle', startPattern: /^\$ bundle install/, endPattern: /^\$/) +] - filter: (log, path) -> - log = @escape(log) - log = @deansi(log) - log = log.replace(/\r/g, '') - log = @number(log, path) - log = @fold(log) - log = log.replace(/\n/g, '') - log +@Travis.Log = Em.Object.extend + init: -> + @set 'folds', [] + @set 'line', 1 - stripPaths: (log) -> - log.replace /\/home\/vagrant\/builds(\/[^\/\n]+){2}\//g, '' + for fold in FOLDS + @addFold fold + + append: (lines) -> + log = @join lines + log = @escape log + log = @deansi log + lines = @split log + + target = @get 'target' + index = 0 + currentFold = @currentFold + + @set 'lineNumber', 1 unless @get 'lineNumber' + + result = [] + + for line in lines + if line == '\r' + @set 'replace', true + else if line == '\n' + @set 'newline', true + index += 1 + else + if currentFold && ( @isFoldEnding(currentFold, line) ) + # end of the fold, send fold to target + if result.length > 0 + result.slice(-1)[0].foldEnd = true + target.appendLog result + + @currentFold = currentFold = null + @set 'foldContinuation', false + result = [] + + if !currentFold && ( currentFold = @foldByStart(line) ) + # beginning new fold, send current lines to target + if result.length > 0 + target.appendLog result + + result = [] + start = index + + payload = { content: line } + + if currentFold + payload.fold = currentFold.get('name') + + if @get 'foldContinuation' + payload.foldContinuation = true + + payload.number = @get('lineNumber') + index + + if @get 'replace' + @set 'replace', false + payload.replace = true + else if @get 'newline' + @set 'newline', false + else if payload.number != 1 + payload.append = true + + result.pushObject payload + + if currentFold + @set 'foldContinuation', true + + if result.length > 0 + if currentFold + @currentFold = currentFold + + target.appendLog result + + nextLineNumber = @get('lineNumber') + index + @set 'lineNumber', nextLineNumber + + join: (lines) -> + if typeof lines == 'string' + lines + else + lines.toArray().join '' + + split: (log) -> + log = log.replace /\r\n/g, '\n' + lines = log.split(/(\n)/) + + result = [] + for line in lines + result.pushObjects line.split(/(\r)/) + + result escape: (log) -> Handlebars.Utils.escapeExpression log - escapeRuby: (log) -> - log.replace /#<(\w+.*?)>/, '#<$1>' - - number: (log, path) -> - path = "#{path}/" - result = '' - $.each log.trim().split('\n'), (ix, line) -> - number = ix + 1 - pathWithNumber = "#{path}#L#{number}" - result += '

%@%@

\n'.fmt(pathWithNumber, number, number, number, line) - result.trim() - deansi: (log) -> log = log.replace(/\r\r/g, '\r') .replace(/\033\[K\r/g, '\r') - .replace(/^.*\r(?!$)/gm, '') .replace(/\[2K/g, '') .replace(/\033\(B/g, '') .replace(/\033\[\d+G/, '') @@ -52,17 +122,11 @@ text += (if classes.length then ('' + part.text + '') else part.text) text.replace /\033/g, '' - fold: (log) -> - log = @unfold(log) - $.each Travis.Log.FOLDS, (name, pattern) -> - log = log.replace(pattern, -> - '
' + arguments[1].trim() + '
' - ) - log + addFold: (fold) -> + @get('folds').pushObject fold - unfold: (log) -> - log.replace /
([\s\S]*?)<\/div>/g, '$1\n' - - location: -> - window.location.hash + foldByStart: (line) -> + @get('folds').find (fold) -> line.match(fold.get('startPattern')) + isFoldEnding: (fold, line) -> + line.match(fold.get('endPattern')) diff --git a/assets/scripts/spec/unit/artifact_spec.coffee b/assets/scripts/spec/unit/artifact_spec.coffee new file mode 100644 index 00000000..4458152e --- /dev/null +++ b/assets/scripts/spec/unit/artifact_spec.coffee @@ -0,0 +1,36 @@ +store = null +record = null + +describe 'Travis.Artifact', -> + beforeEach -> + store = Travis.Store.create() + + afterEach -> + store.destroy() + + describe 'with part of the body loaded', -> + beforeEach => + store.load Travis.Artifact, 1, { id: 1, body: 'first\nsecond\n' } + record = store.find(Travis.Artifact, 1) + + it 'packs the existing part of the body to parts', -> + expect( record.get('parts').toArray() ).toEqual( ['first\nsecond\n'] ) + + it 'adds new chunks of log to parts', -> + record.append('third\n') + expect( record.get('parts').toArray() ).toEqual( ['first\nsecond\n', 'third\n'] ) + + it 'properly handles array observers', -> + called = 0 + observer = { + arrayDidChange: -> called += 1 + arrayWillChange: -> called += 1 + } + + record.get('parts').addArrayObserver observer, + willChange: 'arrayWillChange' + didChange: 'arrayDidChange' + + record.append('something') + + expect(called).toEqual 2 diff --git a/assets/scripts/spec/unit/log_spec.coffee b/assets/scripts/spec/unit/log_spec.coffee new file mode 100644 index 00000000..4c0d1ce9 --- /dev/null +++ b/assets/scripts/spec/unit/log_spec.coffee @@ -0,0 +1,232 @@ +log = null +target = null + +describe 'Travis.Log', -> + beforeEach -> + target = Em.Object.create + calls: [] + appendLog: (payloads) -> + lines = payloads.map (p) -> + line = p.content + delete p.content + line + + @get('calls').pushObject + options: payloads + lines: lines + + log = Travis.Log.create(target: target) + + it 'works with log passed as a string', -> + log.append '1\n2' + + expect( target.get('calls.firstObject.lines') ).toEqual ['1', '2'] + + + it 'splits lines', -> + log.append ['1\r\n2\n\n', '3'] + + expect( target.get('calls.length') ).toEqual 1 + expect( target.get('calls.firstObject.lines') ).toEqual ['1', '2', '', '3'] + + it 'escapes html characters', -> + log.append '<>' + + expect( target.get('calls.firstObject.lines') ).toEqual ['<>'] + + it 'normalizes ansi mess', -> + log.append ['foo\r\r', 'bar'] + + expect( target.get('calls.firstObject.lines') ).toEqual [ 'foo', 'bar' ] + + it 'calls target with folds separation', -> + fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/ + log.addFold fold + + fold = Em.Object.create name: 'qux', startPattern: /^\$ qux/, endPattern: /^\$/ + log.addFold fold + + log.append [ + '1\n', '2\n' + '$ foo --foo\n', '1\n' + '$ bar\n' + '$ baz\n' + '$ qux\n', '1\n', '2\n' + '$ end\n' + ] + + # expect( target.get('calls.length') ).toEqual 5 + lines = target.get('calls').map (call) -> call.lines + options = target.get('calls').map (call) -> call.options + + expect( lines[0] ).toEqual ['1', '2'] + expect( options[0]).toEqual [ { number: 1 }, { number: 2 } ] + + expect( lines[1] ).toEqual ['$ foo --foo', '1'] + expect( options[1]).toEqual [ + { number: 3, fold: 'foo' }, + { number: 4, fold: 'foo', foldContinuation: true, foldEnd: true }] + + expect( lines[2] ).toEqual ['$ bar', '$ baz'] + expect( options[2]).toEqual [{ number: 5 }, { number: 6 }] + + expect( lines[3] ).toEqual ['$ qux', '1', '2'] + expect( options[3]).toEqual [ + { number: 7, fold: 'qux' }, + { number: 8, fold: 'qux', foldContinuation: true }, + { number: 9, fold: 'qux', foldContinuation: true, foldEnd: true }] + + expect( lines[4] ).toEqual ['$ end', ''] + expect( options[4]).toEqual [{ number: 10 }, { number: 11 }] + + it 'works properly when log is started with fold', -> + fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/ + log.addFold fold + + log.append [ + '$ foo --foo\n', '1\n' + '$ bar\n' + ] + + expect( target.get('calls.length') ).toEqual 2 + lines = target.get('calls').map (call) -> call.lines + options = target.get('calls').map (call) -> call.options + + expect( lines[0] ).toEqual ['$ foo --foo', '1'] + expect( options[0]).toEqual [ + { number: 1, fold: 'foo' }, + { number: 2, fold: 'foo', foldContinuation: true, foldEnd: true }] + + expect( lines[1] ).toEqual ['$ bar', ''] + expect( options[1]).toEqual [{ number: 3 }, { number: 4 }] + + it 'works properly for 2 consecutive folds', -> + fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/ + log.addFold fold + + log.append [ + '$ foo --foo\n', '1\n' + '$ foo --bar\n', '2\n' + '$ bar\n' + ] + + expect( target.get('calls.length') ).toEqual 3 + lines = target.get('calls').map (call) -> call.lines + options = target.get('calls').map (call) -> call.options + + expect( lines[0] ).toEqual ['$ foo --foo', '1'] + expect( options[0]).toEqual [ + { number: 1, fold: 'foo' }, + { number: 2, fold: 'foo', foldContinuation: true, foldEnd: true }] + + expect( lines[1] ).toEqual ['$ foo --bar', '2'] + expect( options[1]).toEqual [ + { number: 3, fold: 'foo' }, + { number: 4, fold: 'foo', foldContinuation: true, foldEnd: true }] + + expect( lines[2] ).toEqual ['$ bar', ''] + expect( options[2]).toEqual [{ number: 5 }, { number: 6 }] + + it 'works fine with not finalized fold', -> + fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/ + log.addFold fold + + log.append [ + '$ foo --foo\n', '1\n' + ] + + expect( target.get('calls.length') ).toEqual 1 + lines = target.get('calls').map (call) -> call.lines + options = target.get('calls').map (call) -> call.options + + expect( lines[0] ).toEqual ['$ foo --foo', '1', ''] + expect( options[0]).toEqual [ + { fold: 'foo', number: 1 }, + { fold: 'foo', number: 2, foldContinuation: true }, + { fold: 'foo', number: 3, foldContinuation: true }] + + it 'allows to continue fold', -> + fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/ + log.addFold fold + + log.append [ + '$ foo --foo\n', '1\n' + ] + + log.append '2\n' + + log.append [ + '3\n' + '$ bar\n' + ] + + expect( target.get('calls.length') ).toEqual 4 + lines = target.get('calls').map (call) -> call.lines + options = target.get('calls').map (call) -> call.options + + expect( lines[0] ).toEqual ['$ foo --foo', '1', ''] + expect( options[0]).toEqual [ + { fold: 'foo', number: 1 }, + { fold: 'foo', number: 2, foldContinuation: true }, + { fold: 'foo', number: 3, foldContinuation: true }] + + expect( lines[1] ).toEqual ['2', ''] + expect( options[1]).toEqual [ + { fold: 'foo', number: 3, foldContinuation: true, append: true } + { fold: 'foo', number: 4, foldContinuation: true } + ] + + expect( lines[2] ).toEqual ['3'] + expect( options[2]).toEqual [ + { fold: 'foo', number: 4, foldContinuation: true, append: true, foldEnd: true } + ] + + expect( lines[3] ).toEqual ['$ bar', ''] + expect( options[3]).toEqual [{ number: 5 }, { number: 6 }] + + it 'notifies that the line should be appended', -> + log.append '$ foo\n.' + + log.append '...' + + log.append '..\n$ bar\n' + + expect( target.get('calls.length') ).toEqual 3 + lines = target.get('calls').map (call) -> call.lines + options = target.get('calls').map (call) -> call.options + + expect( lines[0] ).toEqual ['$ foo', '.'] + expect( options[0]).toEqual [{ number: 1 }, { number: 2 }] + + expect( lines[1] ).toEqual ['...'] + expect( options[1]).toEqual [{ append: true, number: 2 }] + + expect( lines[2] ).toEqual ['..', '$ bar', ''] + expect( options[2]).toEqual [{ append: true, number: 2 }, { number: 3 }, { number: 4 }] + + it 'notifies that the line should be replaced', -> + log.append '$ foo\n' + + log.append '\rDownloading 50%' + log.append '\rDownloading 100%\r\n' + + log.append '$ bar\n' + + expect( target.get('calls.length') ).toEqual 4 + lines = target.get('calls').map (call) -> call.lines + options = target.get('calls').map (call) -> call.options + + expect( lines[0] ).toEqual ['$ foo', ''] + expect( options[0]).toEqual [{ number: 1 }, { number: 2 }] + + expect( lines[1] ).toEqual ['', 'Downloading 50%'] + expect( options[1]).toEqual [{ number: 2, append: true }, { number: 2, replace: true }] + + expect( lines[2] ).toEqual ['', 'Downloading 100%', ''] + expect( options[2]).toEqual [{ number: 2, append: true }, { number: 2, replace: true }, { number: 3 }] + + expect( lines[3] ).toEqual ['$ bar', ''] + expect( options[3]).toEqual [{ number: 3, append: true }, { number: 4 }] + + it 'notifies that the line should be replaced even if carriage return is in the middle', -> + diff --git a/assets/scripts/spec/unit/views/log_view_spec.coffee b/assets/scripts/spec/unit/views/log_view_spec.coffee new file mode 100644 index 00000000..fc6394a2 --- /dev/null +++ b/assets/scripts/spec/unit/views/log_view_spec.coffee @@ -0,0 +1,74 @@ +view = null +store = null +record = null + +describe 'Travis.LogView', -> + beforeEach -> + store = Travis.Store.create() + + afterEach -> + store.destroy() + view.remove() + view.destroy() + + it 'works fine with existing log, which is appended', -> + store.load Travis.Artifact, 1, { id: 1, body: '$ start' } + log = Travis.Artifact.find(1) + + Ember.run -> + view = Travis.LogView.create(context: null) + view.append() + + expect( $('#log').length ).toEqual 1 + console.log $('#log') + + job = Ember.Object.create log: log, subscribe: (-> ) + + Ember.run -> + view.set 'context', job + log.set 'isLoaded', true + + expect( view.$('#log p').length ).toEqual 1 + expect( view.$('#log p').text().trim() ).toEqual '1$ start' + + Ember.run -> + log.append('$ end') + + expect( view.$('#log p').length ).toEqual 2 + expect( view.$('#log p').text().trim() ).toEqual '1$ start2$ end' + + it 'works fine with log already attahed to view', -> + store.load Travis.Artifact, 1, { id: 1, body: '$ start' } + log = Travis.Artifact.find(1) + job = Ember.Object.create log: log, subscribe: (-> ) + + Ember.run -> + view = Travis.LogView.create() + view.set('context', job) + view.append() + + Ember.run -> + log.append('end') + + expect( view.$('#log p').length ).toEqual 2 + expect( view.$('#log p').text().trim() ).toEqual '1$ start2end' + + it 'folds items', -> + store.load Travis.Artifact, 1, { id: 1, body: '$ start' } + log = Travis.Artifact.find(1) + job = Ember.Object.create log: log, subscribe: (-> ) + + Ember.run -> + view = Travis.LogView.create() + view.set('context', job) + view.append() + + Ember.run -> + log.append '$ bundle install\n1\n2' + + Ember.run -> + log.append '3\n4\n$ something' + + expect( view.$('#log > p').length ).toEqual 2 + expect( view.$('#log .fold.bundle').length ).toEqual 1 + expect( view.$('#log .fold.bundle > p').length ).toEqual 5 diff --git a/assets/styles/main/log.sass b/assets/styles/main/log.sass index 484d6757..0710e42c 100644 --- a/assets/styles/main/log.sass +++ b/assets/styles/main/log.sass @@ -39,6 +39,10 @@ pre#log &.open height: auto background-image: inline-image('ui/log.fold.open.2.png') + &.show-first-line:not(.open) + height: 36px + p:not(:first-child):not(:last-child) + display: none #log.loading padding: 25px 0 0 10px