390341 - support gzip encoding and content-length for Tinderbox showlog.cgi

Status: RESOLVED FIXED

(Webtools Graveyard :: Tinderbox, enhancement)

Description

[Robert Helmer [:rhelmer]]

Supporting HTTP gzip encoding would reduce transfer sizes, and probably greatly increase perceived transfer time for most users. 

I think that this would be especially pronounced when sending gzipped Tinderbox logs, as they would not have to be uncompressed on the server side before sending.

Comment 1

[Robert Helmer [:rhelmer]]

(In reply to comment #0)
> Supporting HTTP gzip encoding would reduce transfer sizes, and probably greatly
> increase perceived transfer time for most users. 

Er, should be greatly *reduce* perceived time :)

Comment 2

[Robert Helmer [:rhelmer]]

I took a look at showlog.cgi tonight, which is where I think the biggest use for this feature would be.

Here is what currently happens:

Build logfile (received via email) is compressed and stored in tree directory. Every time a request is made to showlog.cgi, the compressed logfile is read in it's entirety and either a "brief" or "complete" HTML page is generated.

If we instead generated and stored the "brief" and "complete" HTML pages as gzipped HTML, we simply write the contents of that file to the user agent if "Content-encoding: gzip" is set. This could be a huge win in server processing time as well as bandwidth and load time for the client.

Even if the user agent doesn't support gzip encoding (I can't think of very many nowadays that don't, but it can be checked using the client-side Accept-encoding header), it'd still take less time to uncompress these pages than to rebuild the report each time.

Comment 4

[Robert Helmer [:rhelmer]]

I hacked this up locally and it seems doable, for the most part. I believe that all of the dynamic bits in showlog.cgi could be moved to helper functions which are called when the original incoming build log email is processed (it's all printed directly to stdout right now as it's processed), with the exception of notes (which are entered when a build is "starred").

Notes go into the "build comments", here is an example:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1274159009.1274159743.31762.gz

There are ways to enable the feature without preserving the current output (using ajax, iframe, etc.), but these seem like a much bigger task. I am assuming that having build notes on these pages is a useful feature that no one wants to sacrifice.

My only idea so far is to uncompress the first few lines of the report, insert the notes, then compress this and append the rest of the file. I think it should be possible to determine what the content-length will be, so at least the rest of the file could be printed to stdout as it is read.

Maybe someone else can correct the above, or has a better idea?

Comment 5

[(not currently active) Ted Mielczarek]

Can you just regenerate the cached HTML when build notes are added? Might take a second or two, but still better than what we're doing now.

(And yeah, we can't live without being able to star builds, presently.)

Comment 6

[Robert Helmer [:rhelmer]]

(In reply to comment #5)
> Can you just regenerate the cached HTML when build notes are added? Might take
> a second or two, but still better than what we're doing now.

Yes, I think this would work fine. Thanks!

One thing I just noticed is that there already is a cache in place for the "brief" log.

The README says that this file gets updated when the log does, but my read of the source indicates that it gets created the first time the brief log is loaded:

http://mxr.mozilla.org/mozilla/source/webtools/tinderbox/showlog.cgi#112

The "Build Error Summary" and following sections are cached; notes and links above that are done dynamically at request-time, so this approach would have the same problem with regard to gzipping that I was stumbling on in comment 4. 

I think that this older approach should be removed, and the full and brief files should be gzipped and updated when the log is updated or when notes are added.

Comment 7

[(not currently active) Ted Mielczarek]

Fully agree.

Comment 8

[Robert Helmer [:rhelmer]]

Attachment: PoC gzip-encoding for brief/full log reports

Here is a working proof-of-concept for the approach we discussed in IRC. 
This does not implement caching (yet), but does the following:

* send back gzipped content if accept-encoding request header contains gzip
* remove global dependencies from all functions in showlog.cgi and move the functions to tbglobals.pl (so they can be used by other scripts, to build the cache when email or notes come in)
* remove print_fragment (I can't figure out how to get it working, am I wrong here? I've never seen this feature used)
* remove print_log_section (looks like dead code, is not called from anywhere)
* remove existing brief.html cache mechanism
* comment out EmitHtmlTitleAndHeader until we decide what approach to take for output

This makes showlog.cgi much simpler, although there's still room for improvement. I am not sure if tbglobals.pl is the right place to move all this, but it seems to be the place for sharing code between different parts of tinderbox.

I am wondering what you think about the general idea of passing around a filehandle that might be STDOUT or might be gzip (which may be writing to STDOUT or a file). This same approach could be used in other parts of Tinderbox, if it makes sense. In the case where we do have a cache we should be able to just read the file and write directly to STDOUT.

Finally, I think we should construct the cache at request time if it does not exist for some reason (e.g. previous version of Tinderbox was in place when the log was received). Then there will be just one code path for displaying the brief and full reports: either cat the file to the network, or uncompress it and cat it (in the case where the client doesn't set Accept-Encoding: gzip).

Comment 10

[Mike Taylor [:bear]]

(In reply to comment #8)
> Created an attachment (id=446387) [details]
> PoC gzip-encoding for brief/full log reports
> 
> Here is a working proof-of-concept for the approach we discussed in IRC. 
> This does not implement caching (yet), but does the following:
> 
> * send back gzipped content if accept-encoding request header contains gzip
> * remove global dependencies from all functions in showlog.cgi and move the
> functions to tbglobals.pl (so they can be used by other scripts, to build the
> cache when email or notes come in)
> * remove print_fragment (I can't figure out how to get it working, am I wrong
> here? I've never seen this feature used)
> * remove print_log_section (looks like dead code, is not called from anywhere)
> * remove existing brief.html cache mechanism
> * comment out EmitHtmlTitleAndHeader until we decide what approach to take for
> output
> 
> This makes showlog.cgi much simpler, although there's still room for
> improvement. I am not sure if tbglobals.pl is the right place to move all this,
> but it seems to be the place for sharing code between different parts of
> tinderbox.

until a true refactoring takes place, tbglobals.pl is the least smelly place to place it IMO

> 
> I am wondering what you think about the general idea of passing around a
> filehandle that might be STDOUT or might be gzip (which may be writing to
> STDOUT or a file). This same approach could be used in other parts of
> Tinderbox, if it makes sense. In the case where we do have a cache we should be
> able to just read the file and write directly to STDOUT.

+1 to this - it will allow people who do downstream changes to the code to have a single variable to send data to without the propagation of if/else checks that otherwise would be required

> 
> Finally, I think we should construct the cache at request time if it does not
> exist for some reason (e.g. previous version of Tinderbox was in place when the
> log was received). Then there will be just one code path for displaying the
> brief and full reports: either cat the file to the network, or uncompress it
> and cat it (in the case where the client doesn't set Accept-Encoding: gzip).

again +1

Comment 11

[Mike Taylor [:bear]]

Comment on attachment 446387 [details] [diff] [review]
PoC gzip-encoding for brief/full log reports

I don't see anything from a code reading, but for sure we are going to need to run this on a staging tinderbox and see what breaks.

Comment 12

[Robert Helmer [:rhelmer]]

Thanks for the feedback! 

We do definitely need to run this on staging and bang on it for a bit when it's ready. I am a little concerned that the fragment feature might need to be re-added, but I really want to determine if it's actually working or not first.

Also I am worried that some of these functions may be modifying the vars with the assumption that they are global; I think that changing this is the right thing to do so it's probably worth the fallout (IMHO) to get away from using and mutating globals like this. 

I have been doing very basic local testing though and it seems ok; having an automated functional test suite (could be very basic) would be a huge timesaver here.

Comment 13

[Robert Helmer [:rhelmer]]

Attachment: add per-request caching and content-length

Build on the previous patch:

* check for cache file and build at request time if it does not exist
* add content-length header if cache file exists

Only remaining task (I think) is to tighten up and generalize this caching approach, and make it available to other code (so the caches can be built when the email is received and/or notes are updated).

showlog.cgi goes through quite a bit of machination to do this right now, I would like to simplify that so we don't have that same rigmarole in three places.

Comment 14

[Robert Helmer [:rhelmer]]

I've been loading logs from production and comparing them in a test env and everything seems fine so far. I've diffed the output and only found expected differences. 

One thing this patch definitely needs is for showlog.cgi to check that the underlying build exists and exit as soon as possible (before writing cache files or doing any work, so unexpected errors don't cause corruption in the caches). Right now production gets pretty far in processing if you give it an invalid file so this is not a new issue, but it impacts the integrity of the cache so it's more important now: http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/123.gz

Comment 15

[Robert Helmer [:rhelmer]]

I noticed something a little disturbing in production, the "brief" and "full" reports are exactly the same:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1274332018.1274332772.29524.gz
vs.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1274332018.1274332772.29524.gz&fulltext=1

Looks like the parsers don't really work anymore? Or maybe I am missing something here... the brief logs don't look very brief in any case. I checked a somewhat random sample of different logs, so maybe it still works in some cases.

With this gzip patch this test log goes from 4MB down to 400k, which is great for transfer time.. but loading that 4MB log into the browser is still pretty painful, at least on my MBP (Firefox is completely unresponsive for a second or two when the transfer is finished, which does not feel nice). Having a "brief" log that only shows errors would probably make this feel much nicer (which I think is how tinderbox is supposed to work, and used to work, and maybe still does sometimes?).

Maybe someone can shed light here on why the brief logs aren't very brief?

Comment 16

[Robert Helmer [:rhelmer]]

Attachment: Exit early if logfile does not exist.

Comment 17

[(not currently active) Ted Mielczarek]

(In reply to comment #15)
> Maybe someone can shed light here on why the brief logs aren't very brief?

IIRC, if the errorparser doesn't find any errors, then it doesn't actually generate a brief log, you just get the full log.

Comment 18

[Robert Helmer [:rhelmer]]

(In reply to comment #17)
> (In reply to comment #15)
> > Maybe someone can shed light here on why the brief logs aren't very brief?
> 
> IIRC, if the errorparser doesn't find any errors, then it doesn't actually
> generate a brief log, you just get the full log.

That makes sense, thanks. I went looking for logs with errors and found that it's working as you describe, it skips a bunch of lines if there's an error:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1274376458.1274377035.18775.gz

But no lines are skipped if there are no errors.

I am definitely veering outside of the scope of this bug, but I just want to point out that if you want a better experience loading logs in the browser from Tinderbox I definitely suggest cutting down on the size of the full logs if possible, and perhaps making brief logs briefer even in the case where there are no errors. Loading a file this large into the browser is painful no matter how it's transferred.

Comment 19

[(not currently active) Ted Mielczarek]

Probably deserves a second bug, yeah, that experience sucks.

Comment 20

[Robert Helmer [:rhelmer]]

Attachment: create gzip cache on addnote or processbuild

I have generalized the cache creation to a relatively simple function in tbglobals called create_cache:

create_cache($errorparser, $fulltext, $logfile, $tree, $buildtime, $buildname);

This is now the only entry point to all the old showlog.cgi code that I moved to tbglobals. 

The caches are first written to a tmp file, then moved when the process is finished (to avoid users seeing a partial log while the cache is being rebuilt, in the case that a cache is being re-created).

$fulltext is either 0 or 1, to mean brief or full (this matches the HTTP parameter passed to showlog.cgi).

This function is called in the following places:

1) in showlog.cgi, if the requested cache does not exist
2) in addnote.cgi (when a build is "starred")
3) in processbuild.pl (when a new build email is received).

I don't like how #2 makes the user wait when submitting a note. Any ideas for dealing with that?

Besides the concern with addnote.cgi, I think this is pretty much ready for a real review.

Comment 21

[Robert Helmer [:rhelmer]]

Attachment: use PID in tmp cache filename

Same as last time, but allow for multiple processes attempting to rebuild the cache by putting the PID in the tmp cache filename (whichever process does the mv last wins).

There *might* be a race condition here but I think because the notes.txt is written before the cache files it will not be an issue if e.g. multiple users add notes around the same time.. 

However if needed then I don't think using a lock would be too onerous here since this shouldn't happen very often.

Comment 22

[Robert Helmer [:rhelmer]]

Attachment: fixup banner/blurb printing

Comment 23

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Any ETA on this?  This is I believe the root cause of things like starring tinderbox orange taking so long; clicking on a log in tbpl currently takes around 20-30 seconds for the log to load on the office network, whereas with cache + gzip encoding, it takes around 1 second.  Would be a pretty big usability win there.

Comment 24

[Mike Taylor [:bear]]

This has been leering at me from my review queue but Android and OS X work has trumped any time adjusting i've done.

Your comment helps push it higher in my queue - it's not forgotten tho

Comment 25

[Robert Helmer [:rhelmer]]

(In reply to comment #23)
> Any ETA on this?  This is I believe the root cause of things like starring
> tinderbox orange taking so long; clicking on a log in tbpl currently takes
> around 20-30 seconds for the log to load on the office network, whereas with
> cache + gzip encoding, it takes around 1 second.  Would be a pretty big
> usability win there.

Perhaps a shortcut instead of having to patch tinderbox server would be something like bug 571085 (have Apache gzip anything that comes out of showlog.cgi).

Tinderbox would still be doing gunzip and error-log parsing on the original log per-request so it is not as efficient as the patch I posted, but at least the HTTP output would be gzipped.

Comment 26

[Robert Helmer [:rhelmer]]

(In reply to comment #25)
> Perhaps a shortcut instead of having to patch tinderbox server would be
> something like bug 571085 (have Apache gzip anything that comes out of
> showlog.cgi).
> 
> Tinderbox would still be doing gunzip and error-log parsing on the original log
> per-request so it is not as efficient as the patch I posted, but at least the
> HTTP output would be gzipped.

Tested locally and mod_deflate seems to work with CGIs ok, filed bug 574524 to offload the gzip-encoding job to Apache.

Comment 27

[Robert Helmer [:rhelmer]]

Apache mod_deflate doing gzip (bug 574524) is live on tinderbox-stage now and seems to help a lot, I am going to put more details on the tests I've done in that bug.

Can people please help test http://tinderbox-stage.mozilla.org so this can go live?

Comment 28

[Robert Helmer [:rhelmer]]

(In reply to comment #27)
> Can people please help test http://tinderbox-stage.mozilla.org so this can go
> live?

This seems fine in most cases but latest minefield just beachballs on my mbp for minutes if I load a particularly large one:

http://tinderbox-stage.mozilla.org/showlog.cgi?log=Firefox/1277845327.1277850370.21087.gz

The production equivalent of that is:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1277845327.1277850369.10000.gz&fulltext=1

The latter takes way longer to fully load but the browser is at least usable in the interim...

Comment 29

[Robert Helmer [:rhelmer]]

(In reply to comment #28)
> The production equivalent of that is:
> 
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1277845327.1277850369.10000.gz&fulltext=1

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1277845327.1277850369.10000.gz is more exactly equivalent, no significant difference in this case though.

Comment 30

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

This is because those pages are still served as UTF8, so we end up hitting bug 566066 -- we just hit it a lot more quickly when you get the gzip'd data.  It would be far, far better if these pages forced a content-encoding of ascii -- someone who really needs to see the UTF8 can just select that encoding manually.

Try loading

http://vlad.off.net/misc/fetchlog.php?log=http%3A%2F%2Ftinderbox.mozilla.org%2Fshowlog.cgi%3Flog%3DFirefox%2F1277845327.1277850369.10000.gz

which is that same log, except going through my script which forces the encoding.

Comment 31

[Robert Helmer [:rhelmer]]

Attachment: force charset=us-ascii for showlog.cgi

Comment 32

[Robert Helmer [:rhelmer]]

Attachment: force charset=iso8859-1 for showlog.cgi

Comment 33

[Robert Helmer [:rhelmer]]

Attachment: force charset=iso8859-1 for showlog.cgi

oh bugzilla how I've missed your ways

Comment 34

[Reed Loden [:reed]]

Comment on attachment 455058 [details] [diff] [review]
force charset=iso8859-1 for showlog.cgi

This regresses bug 474657.

Comment 35

[Robert Helmer [:rhelmer]]

(In reply to comment #34)
> (From update of attachment 455058 [details] [diff] [review])
> This regresses bug 474657.

Yes it does. It's not clear to me from reading bug 474657 how bad it is (does it obscure errors? does it just look ugly?)

How bad is bug 474657? Is it worth regressing to get (much) faster-loading logs?

Failing that are there any alternative workarounds for bug 566066 we can consider?

Comment 36

[Robert Helmer [:rhelmer]]

(In reply to comment #35)
> (In reply to comment #34)
> > (From update of attachment 455058 [details] [diff] [review] [details])
> > This regresses bug 474657.
> 
> Yes it does. It's not clear to me from reading bug 474657 how bad it is (does
> it obscure errors? does it just look ugly?)
> 
> How bad is bug 474657? Is it worth regressing to get (much) faster-loading
> logs?

The dup bug 446505 has an example.

Comment 37

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Regressing 474657 is perfectly fine, IMO -- we just need to communicate that people who need UTF8 can explicitly select that encoding.  The garbling in there is due to msvc using curly quotes for the output, but even then it's "straigtfroward" grabling, it doesn't make the log unreadable.

Comment 38

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

One way to fix the gcc using curly quotes issue is to just set LC_ALL=C in the build environment that gets sent to the buildmasters; that way it won't try to send any unicode goop.

Comment 39

[Robert Helmer [:rhelmer]]

(In reply to comment #38)
> One way to fix the gcc using curly quotes issue is to just set LC_ALL=C in the
> build environment that gets sent to the buildmasters; that way it won't try to
> send any unicode goop.

I will file a separate bug about that.

Comment 40

[Robert Helmer [:rhelmer]]

(In reply to comment #37)
> Regressing 474657 is perfectly fine, IMO -- we just need to communicate that
> people who need UTF8 can explicitly select that encoding.  The garbling in
> there is due to msvc using curly quotes for the output, but even then it's
> "straigtfroward" grabling, it doesn't make the log unreadable.

I agree, this seems like the lesser evil here. We're talking about several minutes versus a few seconds to load a typical build log (see comment #30).

reed made the point in irc that bug 566066 is a Firefox bug and should be fixed in Firefox. I am (very) sympathetic to that viewpoint, but I would argue that not having ASCII encoded, gzipped logs is slowing down development work on Firefox ;)

I feel like someone is going to be unhappy no matter what we do. I am inclined to regress bug 474657, does someone else need to break the tie here? Take it to the newsgroups (which one)?

Perhaps this issue should be spun out to a separate bug that depends on bug 566066 (so it can be reverted when that one is closed).

Comment 41

[Robert Helmer [:rhelmer]]

(In reply to comment #40)
> (In reply to comment #37)
> Perhaps this issue should be spun out to a separate bug that depends on bug
> 566066 (so it can be reverted when that one is closed).

On further reflection, why not reopen bug 474657 and discuss there? That is probably the right place to set dependencies like bug 566066 and setting the build environment locale to something else like comment #37 suggests.

My main concern is not surprising people who expect the current behavior, they are probably CC'd on bug 474657 for the most part.

I don't have time to do this right now but if no one else has a better plan I will do this sometime this weekend.

Comment 42

[Robert Helmer [:rhelmer]]

(In reply to comment #41)
> (In reply to comment #40)
> > (In reply to comment #37)
> > Perhaps this issue should be spun out to a separate bug that depends on bug
> > 566066 (so it can be reverted when that one is closed).
> 
> On further reflection, why not reopen bug 474657 and discuss there? That is
> probably the right place to set dependencies like bug 566066 and setting the
> build environment locale to something else like comment #37 suggests.

Reopened bug 474657 and set to block this one.

(In reply to comment #39)
> (In reply to comment #38)
> > One way to fix the gcc using curly quotes issue is to just set LC_ALL=C in the
> > build environment that gets sent to the buildmasters; that way it won't try to
> > send any unicode goop.
> 
> I will file a separate bug about that.

I will file this (or not) depending on what happens in bug 474657, leaving it alone for now.

Comment 43

[Robert Helmer [:rhelmer]]

(In reply to comment #38)
> One way to fix the gcc using curly quotes issue is to just set LC_ALL=C in the
> build environment that gets sent to the buildmasters; that way it won't try to
> send any unicode goop.

Since bug 474657 was re-closed, I've opened bug 577310 to get this set in the build environment.

While this should help with build logs, I think there are legitimate cases when other types of logs (many test logs display filenames which contain unicode characters, I have been told).

This might be a good interim approach, until bug 566066 is fixed or an effective workaround is found:

1) patch tinderbox so encoding can be specified
2) if encoding is ascii, set content-type to text/html text/html; charset=iso8859-1
3) if encoding is anything else, set content-type to application/x-gzip

#3 means that UTF-8 (and anything non-ascii) will offer a gzip file for download, which the user can open in another application.

Comment 44

[Robert Helmer [:rhelmer]]

(In reply to comment #28)
> (In reply to comment #27)
> > Can people please help test http://tinderbox-stage.mozilla.org so this can go
> > live?
> 
> This seems fine in most cases but latest minefield just beachballs on my mbp
> for minutes if I load a particularly large one:
> 
> http://tinderbox-stage.mozilla.org/showlog.cgi?log=Firefox/1277845327.1277850370.21087.gz
> 
> The production equivalent of that is:
> 
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1277845327.1277850369.10000.gz&fulltext=1
> 
> The latter takes way longer to fully load but the browser is at least usable in
> the interim...

The more I test this, the harder I find to reproduce it.. I'll try using Firefox instead of Minefield.

At this point I think the gzip-encoding change on tinderbox-stage is better overall and we should move forward with it while continuing to track these other issues.

Comment 45

[Robert Helmer [:rhelmer]]

Yeah I can't reproduce the severe beach-balling I was getting before loading that log from tinderbox-stage, using a fresh profile on the latest Firefox release or latest nightly.

Thanks for philor for trying (and not being able) to reproduce this.

I don't think there's a reason to hold for a fix or workaround on bug 566066. I'll file a bug to get this enabled in production.

Comment 46

[Robert Helmer [:rhelmer]]

bug 577324 enabled gzip-encoding for all CGIs, which satisfies at least part of this bug. If there is any fallout due to this I will help address it.

Tinderbox *should* be doing caching for brief logs (although it's been inconsistent in my local testing) so the overhead of this versus what I was working towards with attachment 577324 [details] [diff] [review] should be minimal.

Barring any problems, I do not intend to keep working on this, if anyone else feels it needs to be reopened feel free to do so and change the assignee.

Comment 47

[Robert Helmer [:rhelmer]]

(In reply to comment #46)
> Tinderbox *should* be doing caching for brief logs (although it's been
> inconsistent in my local testing) so the overhead of this versus what I was
> working towards with attachment 577324 [details] [diff] [review] should be minimal.

I meant to say attachment 446579 [details] [diff] [review]

Comment 48

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

The easy and effective workaround is to force iso-8859-1, which as phil stated in the other bug is to "intentionally serve tinderbox logs with an encoding which is not capable of representing all the characters in the log".

The net result of that change would be:

- For 95% of developers, they will just have very fast loading tinderbox pages, with random bits of garbage here or there from gcc (until bug 577310 is fixed)

- For the 5% of developers that need to see Thai line break test details, they can manually select a UTF8 encoding.

It's not like the data is lost or thrown away...

Comment 49

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Filed bug 581164 on the remaining force-ascii issue to centralize discussion there.