Add reporting for how long narrowing takes in the wild.

I'd also like to add a database table to actually store the values
that we get out of this and our send message requests for future
inspection, but for now, grepping logs+statsd is good enough.

(imported from commit 99ef179651850217fe6e82c5e928d122ca91101e)

static/js/narrow.js

@@ -96,7 +96,30 @@ exports.stream = function () {
     return undefined;
 };
 
+function report_narrow_time(initial_core_time, initial_free_time, network_time) {
+    $.ajax({
+        dataType: 'json', // This seems to be ignored. We still get back an xhr.
+        url: '/json/report_narrow_time',
+        type: 'POST',
+        data: {"initial_core": initial_core_time.toString(),
+               "initial_free": initial_free_time.toString(),
+               "network": network_time.toString()}
+    });
+}
+
+function maybe_report_narrow_time(msg_list) {
+    if (msg_list.network_time === undefined || msg_list.initial_core_time === undefined ||
+        msg_list.initial_free_time === undefined) {
+        return;
+    }
+    report_narrow_time(msg_list.initial_core_time - msg_list.start_time,
+                       msg_list.initial_free_time - msg_list.start_time,
+                       msg_list.network_time - msg_list.start_time);
+
+}
+
 exports.activate = function (operators, opts) {
+    var start_time = new Date();
     // most users aren't going to send a bunch of a out-of-narrow messages
     // and expect to visit a list of narrows, so let's get these out of the way.
     notifications.clear_compose_notifications();
@@ -177,13 +200,14 @@ exports.activate = function (operators, opts) {
         current_msg_list.pre_narrow_offset = current_msg_list.selected_row().offset().top - viewport.scrollTop();
     }
 
-    narrowed_msg_list = new MessageList('zfilt', current_filter, {
+    var msg_list = new MessageList('zfilt', current_filter, {
         collapse_messages: ! current_filter.is_search(),
         muting_enabled: muting_enabled,
         summarize_read: this.summary_enabled()
     });
+    msg_list.start_time = start_time;
 
-
+    narrowed_msg_list = msg_list;
     current_msg_list = narrowed_msg_list;
 
     function maybe_select_closest() {
@@ -235,6 +259,8 @@ exports.activate = function (operators, opts) {
             if (defer_selecting_closest) {
                 maybe_select_closest();
             }
+            msg_list.network_time = new Date();
+            maybe_report_narrow_time(msg_list);
         },
         cont_will_add_messages: false
     });
@@ -279,6 +305,11 @@ exports.activate = function (operators, opts) {
     $(document).trigger($.Event('narrow_activated.zulip', {msg_list: narrowed_msg_list,
                                                             filter: current_filter,
                                                             trigger: opts.trigger}));
+    msg_list.initial_core_time = new Date();
+    setTimeout(function () {
+        msg_list.initial_free_time = new Date();
+        maybe_report_narrow_time(msg_list);
+    }, 0);
 };
 
 // Activate narrowing with a single operator.

zerver/views/__init__.py

@@ -2005,6 +2005,18 @@ def json_report_send_time(request, user_profile,
         statsd.timing("endtoend.displayed_time.%s" % (statsd_key(user_profile.realm.domain, clean_periods=True),), displayed)
     return json_success()
 
+@authenticated_json_post_view
+@has_request_variables
+def json_report_narrow_time(request, user_profile,
+                            initial_core=REQ(converter=to_non_negative_int),
+                            initial_free=REQ(converter=to_non_negative_int),
+                            network=REQ(converter=to_non_negative_int)):
+    request._log_data["extra"] = "[%sms/%sms/%sms]" % (initial_core, initial_free, network)
+    statsd.timing("narrow.initial_core.%s" % (statsd_key(user_profile.realm.domain, clean_periods=True),), initial_core)
+    statsd.timing("narrow.initial_free.%s" % (statsd_key(user_profile.realm.domain, clean_periods=True),), initial_free)
+    statsd.timing("narrow.network.%s" % (statsd_key(user_profile.realm.domain, clean_periods=True),), network)
+    return json_success()
+
 @authenticated_json_post_view
 @has_request_variables
 def json_report_error(request, user_profile, message=REQ, stacktrace=REQ,

zproject/urls.py

@@ -126,6 +126,7 @@ urlpatterns += patterns('zerver.views',
     url(r'^json/get_profile$',              'json_get_profile'),
     url(r'^json/report_error$',             'json_report_error'),
     url(r'^json/report_send_time$',         'json_report_send_time'),
+    url(r'^json/report_narrow_time$',       'json_report_narrow_time'),
     url(r'^json/update_message_flags$',     'json_update_flags'),
     url(r'^json/register$',                 'json_events_register'),
     url(r'^json/upload_file$',              'json_upload_file'),