Merge lp:~huwshimi/launchpad/ajax-time into lp:launchpad

[Huw Wilkins]

[r=lifeless,wgrant][no-qa] Added a visible log of all AJAX events.

We want to expose the time AJAX events take. This branch adds a visible log of all AJAX events to the user logout area. It exposes time taken, the internal AJAX event id, HTTP status and OOPS ID (if applicable).

The log also highlights if the AJAX event takes more than 1 second.

A screencast can be found here: http://people.canonical.com/~huwshimi/ajax_time_log.ogv

[William Grant (wgrant)]

Looks really nice, but a few comments:

 - That JS should be somewhere other than the template. Probably in a new file in lib/lp/app/javascript.
 - The spacing around the new link is also a little off... it might be best to just remove the • from the render time.
 - You construct HTML in JS with string concatenation. While the values that you're including should always be safe, I'd prefer if you constructed a node from a literal string and injected the text using YUI/DOM methods.
 - Could the click handler use toggleClass instead of add/removeClass?

review: Needs Fixing (code*)

[Huw Wilkins (huwshimi)]

> - That JS should be somewhere other than the template. Probably in a new file
> in lib/lp/app/javascript.

Done.

> - The spacing around the new link is also a little off... it might be best to
> just remove the • from the render time.

Fixed. Not great, but better.

> - You construct HTML in JS with string concatenation. While the values that
> you're including should always be safe, I'd prefer if you constructed a node
> from a literal string and injected the text using YUI/DOM methods.

Done.

> - Could the click handler use toggleClass instead of add/removeClass?

Absolutely. Thanks for educating me.

[William Grant (wgrant)]

Looks much better, thanks. A couple of remaining niggles:

 - Can you merge the two visible_render_time sections in base-layout.pt?
 - I think your JS XHTML construction could be a little cleaner still. I've pushed up some suggestions to lp:~wgrant/launchpad/ajax-time.

review: Approve (code*)

[Huw Wilkins (huwshimi)]

> - Can you merge the two visible_render_time sections in base-layout.pt?
> - I think your JS XHTML construction could be a little cleaner still. I've
> pushed up some suggestions to lp:~wgrant/launchpad/ajax-time.

Done and done.

[Robert Collins (lifeless)]

/* Maximum amount of time we want AJAX requests to take, in seconds.

-> perhaps 'requests slower than this are marked as 'slow''. Also suggest s/MAX/OK/ or similar - its not a cap on the duration the request takes, but a threshold for reporting.

This is kindof trivial, but likely to confuse, I think.

review: Approve

=== modified file 'lib/canonical/launchpad/icing/style-3-0.css'
--- lib/canonical/launchpad/icing/style-3-0.css	2011-03-29 07:24:43 +0000
+++ lib/canonical/launchpad/icing/style-3-0.css	2011-03-30 06:26:31 +0000
@@ -1102,7 +1102,7 @@
     font-size: 12px;
     text-decoration: underline;
     }
-.unseen {
+.unseen, .hidden {
     display: none;
     }
 .invisible-link {
@@ -1169,10 +1169,46 @@
     }
 #rendertime {
     float: left;
-    margin: 0.2em 1.2em 0 0;
+    margin: 0.1em 1.2em 0 0;
     color: #666;
     font-size: 10px;
     }
+#ajax-time {
+    float: left;
+    margin: 0 1.2em 0 0.2em;
+    position: relative;
+    }
+#ajax-time-list {
+    position: absolute;
+    z-index: 10;
+    top: 20px;
+    right: 0;
+    width: 200px;
+    background-color: #f2f2f2;
+    border: 2px solid #fff;
+    -moz-box-shadow: 0 0 5px rgba(0, 0, 0, 0.3);
+    -webkit-box-shadow: 0 0 5px rgba(0, 0, 0, 0.3);
+    box-shadow: 0 0 5px rgba(0, 0, 0, 0.3);
+    -webkit-border-radius: 4px;
+    -moz-border-radius: 4px;
+    border-radius: 4px;
+    }
+#ajax-time-list li {
+    border-bottom: 1px solid #e0e0e0;
+    padding: 3px 5px;
+    }
+#ajax-time-list li:last-child {
+    border-bottom: none;
+    }
+#ajax-time-list li span {
+    color: #999;
+    font-size: 11px;
+    display: block;
+    }
+#ajax-time-list strong.warning {
+    color: #f00;
+    background-color: transparent;
+    }
 div.watermark-apps-portlet {
     clear: both;
     margin-bottom: .5em;

=== modified file 'lib/canonical/launchpad/templates/launchpad-loginstatus.pt'
--- lib/canonical/launchpad/templates/launchpad-loginstatus.pt	2011-02-07 07:39:36 +0000
+++ lib/canonical/launchpad/templates/launchpad-loginstatus.pt	2011-03-30 06:26:31 +0000
@@ -9,7 +9,13 @@
 <div id="logincontrol" tal:condition="view/logged_in">
   <form action="+logout" method="post">
     <input type="hidden" name="loggingout" value="1" />
-    <div id="rendertime" tal:condition="request/features/visible_render_time">Loading... &bull;</div>
+    <div id="rendertime" tal:condition="request/features/visible_render_time">Loading...</div>
+    <div id="ajax-time" tal:condition="request/features/visible_render_time">
+        <a href="" class="js-action">AJAX Log &darr;</a>
+        <ul id="ajax-time-list" class="hidden">
+            <li class="no-events">No AJAX events detected</li>
+        </ul>
+    </div>
     <a tal:replace="structure request/lp:person/fmt:name_link" /> &bull;
     <input type="submit" name="logout" value="Log Out" />
   </form>

=== added file 'lib/lp/app/javascript/ajax_log.js'
--- lib/lp/app/javascript/ajax_log.js	1970-01-01 00:00:00 +0000
+++ lib/lp/app/javascript/ajax_log.js	2011-03-30 06:26:31 +0000
@@ -0,0 +1,85 @@
+/* Log time taken for AJAX requests.
+*/
+function start_ajax_logging() {
+    /* Requests slower than this are marked as slow. Value in seconds.
+    */
+    var AJAX_OK_TIME = 1;
+    
+    LPS.use('node', 'lazr.anim', function(Y) {
+        Y.on('contentready', function() {
+            var node = Y.one('#ajax-time-list');
+            var ajax_request_times = {};
+            var ajax_menu_animating = false;
+            var flash_menu = Y.lazr.anim.green_flash({node:'#ajax-time'});
+            flash_menu.on('end', function() {
+                ajax_menu_animating = false;
+            });
+            /* When an AJAX event starts, record the time.
+            */
+            Y.on('io:start', function(transactionid) {
+                var now = new Date();
+                ajax_request_times[transactionid] = now;
+            });
+            /* When an AJAX event finishes add it to the log.
+            */
+            Y.on('io:complete', function(transactionid, arguments) {
+                /* The AJAX event has finished so record the time.
+                */
+                var finish_time = new Date();
+                /* Remove the initial message in the log.
+                */
+                Y.all('#ajax-time-list li.no-events').remove();
+                if (ajax_request_times[transactionid]) {
+                    var start_time = ajax_request_times[transactionid];
+                    /* The time take for the AJAX event, in seconds.
+                    */
+                    var time_taken = (finish_time - start_time)/1000;
+                    var log_node = Y.Node.create(
+                        '<li>Time: <strong></strong><span></span></li>');
+                    log_node.addClass('transaction-' + transactionid);
+                    log_node.one('strong').set(
+                        'text', time_taken.toFixed(2) + ' seconds');
+                    /* If the AJAX event takes longer than AJAX_OK_TIME
+                       then add a warning.
+                    */
+                    if (time_taken > AJAX_OK_TIME) {
+                        log_node.one('strong').addClass('warning');
+                    }
+                    log_node.one('span').set(
+                            'text',
+                            'ID: ' + transactionid +
+                            ', status: ' + arguments.status +
+                            ' (' + arguments.statusText + ')');
+                    var oops = arguments.getResponseHeader('X-Lazr-OopsId');
+                    if (oops) {
+                        var oops_node = Y.Node.create('<a/>');
+                        oops_node.setAttribute(
+                            'href', 'http://pad.lv/' + oops);
+                        oops_node.set('text', oops);
+                        log_node.one('span').append(', OOPS ID:&nbsp;');
+                        log_node.one('span').append(oops_node);
+                    }
+                    node.prepend(log_node);
+                    /* Highlight the new entry in the log.
+                    */
+                    Y.lazr.anim.green_flash({
+                        node: '#ajax-time-list li.transaction-'+transactionid
+                        }).run();
+                    /* Signify a new entry has been added to the log.
+                    */
+                    if (ajax_menu_animating == false) {
+                        flash_menu.run();
+                        ajax_menu_animating = true;
+                    }
+                }
+            });
+            
+            /* Open/close the log.
+            */
+            Y.on('click', function(e) {
+                e.halt();
+                Y.one('#ajax-time-list').toggleClass('hidden');
+            }, '#ajax-time a');
+        }, '#ajax-time');
+    });
+}

=== modified file 'lib/lp/app/templates/base-layout.pt'
--- lib/lp/app/templates/base-layout.pt	2011-02-28 06:28:16 +0000
+++ lib/lp/app/templates/base-layout.pt	2011-03-30 06:26:31 +0000
@@ -191,7 +191,8 @@
     tal:condition="request/features/visible_render_time"
     define="render_time modules/canonical.launchpad.webapp.adapter/summarize_requests;"
     replace='structure string:&lt;script type="text/javascript"&gt;
-  var render_time = "${render_time} &amp;bull;";
+  start_ajax_logging();
+  var render_time = "${render_time}";
   LPS.use("node", function(Y) {
     Y.on("domready", function() {
       var node = Y.one("#rendertime");