10

When I come to Stack Overflow, I typically do so through a link to my reputation tab so I can see any uncommented downvotes on my posts and try to correct whatever problem/error those votes are flagging up.

The past week or so, I've noticed that if I haven't been on the site for (say) 30+ minutes, that link is very slow to load, on the order of 15-20 seconds (it used to be 1-2 seconds — long enough to notice, not to be bothered). The network tab tells me that after a 307 "Internal redirect", it's https://stackoverflow.com/users/157247/t-j-crowder?tab=reputation itself that's slow (rather than one of the things it depends on). Whereas coming "cold" to other pages on SO (such as the questions page) is near-instantaneous. Going back to that same page when I've been there recently is very fast (sub-second); I guess something's been pulled from storage to the active pool or similar. I've eliminated my browser as the issue, and doubt it's my connection (fiber) as it's page-specific.

Obviously, the questions page is going to be much more aggressively optimized than the reputation tab of a user's activity profile, but this is a sudden and significant slowdown.

It's the same without the ?tab=reputation part, as Shadow Wizard suspected.

Could it be looked at and sped back up to, say, at least the 2-4 second range?

Here's an example from this morning (partial HAR with content below):

enter image description here

HAR with content below [thanks muru!] for the long request and a couple after it, with the content and cookies obscured/removed:

{
  "log": {
    "version": "1.2",
    "creator": {
      "name": "WebInspector",
      "version": "537.36"
    },
    "pages": [
      {
        "startedDateTime": "2018-06-28T08:19:07.392Z",
        "id": "page_1",
        "title": "https://stackoverflow.com/users/157247/t-j-crowder",
        "pageTimings": {
          "onContentLoad": 20625.65199995879,
          "onLoad": 20725.040999939665
        }
      }
    ],
    "entries": [
      {
        "startedDateTime": "2018-06-28T08:19:07.391Z",
        "time": 20414.567270903655,
        "request": {
          "method": "GET",
          "url": "https://stackoverflow.com/users/157247/t-j-crowder",
          "httpVersion": "http/2.0",
          "headers": [
            {
              "name": ":method",
              "value": "GET"
            },
            {
              "name": ":authority",
              "value": "stackoverflow.com"
            },
            {
              "name": ":scheme",
              "value": "https"
            },
            {
              "name": ":path",
              "value": "/users/157247/t-j-crowder"
            },
            {
              "name": "upgrade-insecure-requests",
              "value": "1"
            },
            {
              "name": "user-agent",
              "value": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.87 Safari/537.36"
            },
            {
              "name": "dnt",
              "value": "1"
            },
            {
              "name": "accept",
              "value": "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8"
            },
            {
              "name": "accept-encoding",
              "value": "gzip, deflate, br"
            },
            {
              "name": "accept-language",
              "value": "en-US,en;q=0.9"
            },
            {
              "name": "cookie",
              "value": "obscured"
            }
          ],
          "queryString": [],
          "cookies": [
            {
              "name": "obscured",
              "value": "obscured",
              "expires": null,
              "httpOnly": false,
              "secure": false
            }
          ],
          "headersSize": -1,
          "bodySize": 0
        },
        "response": {
          "status": 200,
          "statusText": "",
          "httpVersion": "http/2.0",
          "headers": [
            {
              "name": "status",
              "value": "200"
            },
            {
              "name": "cache-control",
              "value": "private"
            },
            {
              "name": "content-type",
              "value": "text/html; charset=utf-8"
            },
            {
              "name": "content-encoding",
              "value": "gzip"
            },
            {
              "name": "x-frame-options",
              "value": "SAMEORIGIN"
            },
            {
              "name": "set-cookie",
              "value": "obscured"
            },
            {
              "name": "x-request-guid",
              "value": "39e3378f-c174-41a9-8443-e86efc2f9aae"
            },
            {
              "name": "strict-transport-security",
              "value": "max-age=15552000"
            },
            {
              "name": "content-security-policy",
              "value": "upgrade-insecure-requests"
            },
            {
              "name": "accept-ranges",
              "value": "bytes"
            },
            {
              "name": "date",
              "value": "Thu, 28 Jun 2018 08:19:28 GMT"
            },
            {
              "name": "via",
              "value": "1.1 varnish"
            },
            {
              "name": "x-served-by",
              "value": "cache-lcy19240-LCY"
            },
            {
              "name": "x-cache",
              "value": "MISS"
            },
            {
              "name": "x-cache-hits",
              "value": "0"
            },
            {
              "name": "x-timer",
              "value": "S1530173948.852468,VS0,VE20287"
            },
            {
              "name": "vary",
              "value": "Accept-Encoding,Fastly-SSL"
            },
            {
              "name": "x-dns-prefetch-control",
              "value": "off"
            },
            {
              "name": "content-length",
              "value": "32546"
            }
          ],
          "cookies": [
            {
              "name": "acct",
              "value": "obscured",
              "path": "/",
              "domain": ".stackoverflow.com",
              "expires": "2018-12-28T08:19:28.000Z",
              "httpOnly": true,
              "secure": true
            }
          ],
          "content": {
            "size": 122963,
            "mimeType": "text/html",
            "text": "removed"
          },
          "redirectURL": "",
          "headersSize": -1,
          "bodySize": -1,
          "_transferSize": 33141
        },
        "cache": {},
        "timings": {
          "blocked": 4.031270999968052,
          "dns": 7.183000000000001,
          "ssl": 16.643,
          "connect": 34.135,
          "send": 0.22500000000000142,
          "wait": 20295.94099999854,
          "receive": 73.05199990514666,
          "_blocked_queueing": 0.2709999680519104
        },
        "serverIPAddress": "151.101.1.69",
        "connection": "1754317",
        "pageref": "page_1"
      },
      {
        "startedDateTime": "2018-06-28T08:19:27.749Z",
        "time": 30.63231006730348,
        "request": {
          "method": "GET",
          "url": "https://ajax.googleapis.com/ajax/libs/jquery/1.12.4/jquery.min.js",
          "httpVersion": "spdy",
          "headers": [
            {
              "name": "Referer",
              "value": "https://stackoverflow.com/"
            },
            {
              "name": "User-Agent",
              "value": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.87 Safari/537.36"
            },
            {
              "name": "DNT",
              "value": "1"
            }
          ],
          "queryString": [],
          "cookies": [],
          "headersSize": -1,
          "bodySize": 0
        },
        "response": {
          "status": 200,
          "statusText": "",
          "httpVersion": "spdy",
          "headers": [
            {
              "name": "date",
              "value": "Mon, 18 Jun 2018 19:23:39 GMT"
            },
            {
              "name": "content-encoding",
              "value": "gzip"
            },
            {
              "name": "x-content-type-options",
              "value": "nosniff"
            },
            {
              "name": "age",
              "value": "768347"
            },
            {
              "name": "status",
              "value": "200"
            },
            {
              "name": "alt-svc",
              "value": "quic=\":443\"; ma=2592000; v=\"43,42,41,39,35\""
            },
            {
              "name": "content-length",
              "value": "33951"
            },
            {
              "name": "x-xss-protection",
              "value": "1; mode=block"
            },
            {
              "name": "last-modified",
              "value": "Tue, 20 Dec 2016 18:17:03 GMT"
            },
            {
              "name": "server",
              "value": "sffe"
            },
            {
              "name": "vary",
              "value": "Accept-Encoding"
            },
            {
              "name": "content-type",
              "value": "text/javascript; charset=UTF-8"
            },
            {
              "name": "access-control-allow-origin",
              "value": "*"
            },
            {
              "name": "cache-control",
              "value": "public, max-age=31536000, stale-while-revalidate=2592000"
            },
            {
              "name": "accept-ranges",
              "value": "bytes"
            },
            {
              "name": "timing-allow-origin",
              "value": "*"
            },
            {
              "name": "expires",
              "value": "Tue, 18 Jun 2019 19:23:39 GMT"
            }
          ],
          "cookies": [],
          "content": {
            "size": 97163,
            "mimeType": "text/javascript",
            "text": "removed"
          },
          "redirectURL": "",
          "headersSize": -1,
          "bodySize": 0,
          "_transferSize": 0
        },
        "cache": {},
        "timings": {
          "blocked": 3.8903100000321866,
          "dns": -1,
          "ssl": -1,
          "connect": -1,
          "send": 0,
          "wait": 9.665999961681663,
          "receive": 17.076000105589628,
          "_blocked_queueing": 0.3100000321865082
        },
        "serverIPAddress": "216.58.210.42",
        "_fromCache": "disk",
        "pageref": "page_1"
      },
      {
        "startedDateTime": "2018-06-28T08:19:27.749Z",
        "time": 30.954592957976274,
        "request": {
          "method": "GET",
          "url": "https://cdn.sstatic.net/Js/stub.en.js?v=de73985fb2ea",
          "httpVersion": "spdy",
          "headers": [
            {
              "name": "Referer",
              "value": "https://stackoverflow.com/"
            },
            {
              "name": "User-Agent",
              "value": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.87 Safari/537.36"
            },
            {
              "name": "DNT",
              "value": "1"
            }
          ],
          "queryString": [
            {
              "name": "v",
              "value": "de73985fb2ea"
            }
          ],
          "cookies": [],
          "headersSize": -1,
          "bodySize": 0
        },
        "response": {
          "status": 200,
          "statusText": "",
          "httpVersion": "spdy",
          "headers": [
            {
              "name": "date",
              "value": "Thu, 28 Jun 2018 06:09:19 GMT"
            },
            {
              "name": "content-encoding",
              "value": "gzip"
            },
            {
              "name": "age",
              "value": "29160"
            },
            {
              "name": "x-cache",
              "value": "HIT"
            },
            {
              "name": "status",
              "value": "200"
            },
            {
              "name": "content-length",
              "value": "14227"
            },
            {
              "name": "x-served-by",
              "value": "cache-lcy19240-LCY"
            },
            {
              "name": "last-modified",
              "value": "Wed, 27 Jun 2018 22:01:01 GMT"
            },
            {
              "name": "x-timer",
              "value": "S1530166160.551967,VS0,VE0"
            },
            {
              "name": "etag",
              "value": "\"80cd25562ed41:0\""
            },
            {
              "name": "vary",
              "value": "Accept-Encoding,Accept-Encoding"
            },
            {
              "name": "content-type",
              "value": "application/javascript"
            },
            {
              "name": "via",
              "value": "1.1 varnish"
            },
            {
              "name": "cache-control",
              "value": "max-age=604800"
            },
            {
              "name": "accept-ranges",
              "value": "bytes"
            },
            {
              "name": "x-cache-hits",
              "value": "2135"
            }
          ],
          "cookies": [],
          "content": {
            "size": 41272,
            "mimeType": "application/javascript",
            "text": "removed"
          },
          "redirectURL": "",
          "headersSize": -1,
          "bodySize": 0,
          "_transferSize": 0
        },
        "cache": {},
        "timings": {
          "blocked": 3.627592999975197,
          "dns": -1,
          "ssl": -1,
          "connect": -1,
          "send": 0,
          "wait": 10.11800000383705,
          "receive": 17.208999954164028,
          "_blocked_queueing": 0.5929999751970172
        },
        "serverIPAddress": "151.101.1.69",
        "_fromCache": "disk",
        "pageref": "page_1"
      }
    ]
  }
}

Tagging as because it is indeed "...a reproducible problem on the site that [I] believe is due to a mistake, malfunction, or programming error."

  • 1
    Not only reputation tab, the whole user profile takes lots of time to load. I noticed this here on MSE on my own profile, guessing it's related to sheer amount of activity which is pre-loaded, and burdens the server. – Shadow The Dragon Wizard Jun 28 '18 at 7:28
  • @ShadowWizard - It's the suddenness of the change that makes me flag it up. ~10-14 days ago, it was fine. I'll try using a different part of the profile page to see if it has the same problem (but it's that tab, specifically, I refer to for the uncommented downvotes). – T.J. Crowder Jun 28 '18 at 7:32
  • You can right click a row and save as HAR with content. The har file is JSON, and the time should be in .log.entries[0].time. – muru Jun 28 '18 at 8:17
  • @muru - Cool. No surprise there's a way to get the data. I've done that, thanks! – T.J. Crowder Jun 28 '18 at 8:34
  • @ShadowWizard - As you say, it's the same without ?tab=reputation. – T.J. Crowder Jun 28 '18 at 8:36
  • @ShadowWizard for my activity tab at SO, it's worse that that - "Oops! Something Bad Happened" – gnat Jun 29 '18 at 19:59
  • 2
    FWIW, the team is aware of this, but the first attempt to fix it went... Badly. Probably going to need to find a different approach for pulling the reputation history before this is fixed. – Shog9 Jun 29 '18 at 20:44
  • @Shog9 - Thanks for the note! Good to know it's being sorted out. :-) – T.J. Crowder Jun 30 '18 at 6:54
  • @T.J.Crowder consider giving it a try now. My activity tab that has been similarly broken as of late seems to be loading fine now, maybe your is fixed as well – gnat Jul 3 '18 at 9:25
  • 1
    @gnat - Sadly no. 21.2s just now. :-( But knowing they're working on it is good. – T.J. Crowder Jul 3 '18 at 10:51
  • 1.42s this morning. Just one data point, but a promising one. – T.J. Crowder Jul 6 '18 at 6:17
  • @Shog9 - As of this morning, I seem to be consistently getting quick results. Was there a fix? (And: Thanks!) – T.J. Crowder Jul 6 '18 at 8:31
  • 1
    No workable fix just yet, TJ - it seems that SQL Server is now favoring you. – Shog9 Jul 6 '18 at 15:06
  • 1
    @Taryn you mean the slowness is a different issue, not result of a wrong execution plan being selected? Thanks anyway! – Shadow The Dragon Wizard Jul 15 '18 at 17:42
  • 2
    @ShadowWizard Yes the original issue was different. – Taryn Jul 15 '18 at 17:43
8
+100

This should be resolved. After digging into various things, we added a new index and adjusted an existing index specifically for this query. The new execution plan for the query is significantly better and executes much faster for all users. The previous one worked for some users, but not so much for others.

About the time that the query started acting up, we started performing some index/statistics maintenance on the Stack Overflow database as well as DBs, and we're guessing that those maintenance jobs resulted in the SQL engine picking a different plan. By adding a new index to help with the slowness issue, it resolved the original issue.

I have also turned on Query Store for the Stack Overflow database which captures changes to execution plans and allows us to force it to use the plan I want, so if this happens again I'll be able to see if something changed with the cached query plan.

  • It's still somewhat slow here on MSE for initial load, e.g. about 5 seconds for me. Not fatal, but just to let you know. (Further reloads are instant, guess due to caching, but it's slow again if reloading after several hours or a day.) – Shadow The Dragon Wizard Jul 18 '18 at 6:35
  • Update: back to 10 seconds loading here on MSE, and looks like the index is missing on se.com? – Shadow The Dragon Wizard Jul 19 '18 at 14:47
  • @ShadowWizard Better now? – Taryn Jul 19 '18 at 18:37
  • 1
    Yes! Awesome, saw your answer about se.com but what did you do here for MSE? – Shadow The Dragon Wizard Jul 19 '18 at 18:50
  • 1
    @ShadowWizard Same thing as this answer – Taryn Jul 19 '18 at 18:52

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .