11

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."

24
  • 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. Commented Jun 28, 2018 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). Commented Jun 28, 2018 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
    Commented Jun 28, 2018 at 8:17
  • @muru - Cool. No surprise there's a way to get the data. I've done that, thanks! Commented Jun 28, 2018 at 8:34
  • @ShadowWizard - As you say, it's the same without ?tab=reputation. Commented Jun 28, 2018 at 8:36
  • @ShadowWizard for my activity tab at SO, it's worse that that - "Oops! Something Bad Happened"
    – gnat
    Commented Jun 29, 2018 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 Mod
    Commented Jun 29, 2018 at 20:44
  • @Shog9 - Thanks for the note! Good to know it's being sorted out. :-) Commented Jun 30, 2018 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
    Commented Jul 3, 2018 at 9:25
  • 1
    @gnat - Sadly no. 21.2s just now. :-( But knowing they're working on it is good. Commented Jul 3, 2018 at 10:51
  • 1.42s this morning. Just one data point, but a promising one. Commented Jul 6, 2018 at 6:17
  • @Shog9 - As of this morning, I seem to be consistently getting quick results. Was there a fix? (And: Thanks!) Commented Jul 6, 2018 at 8:31
  • 1
    No workable fix just yet, TJ - it seems that SQL Server is now favoring you.
    – Shog9 Mod
    Commented Jul 6, 2018 at 15:06
  • 1
    @Taryn you mean the slowness is a different issue, not result of a wrong execution plan being selected? Thanks anyway! Commented Jul 15, 2018 at 17:42
  • 2
    @ShadowWizard Yes the original issue was different.
    – Taryn StaffMod
    Commented Jul 15, 2018 at 17:43

1 Answer 1

9
+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.

5
  • 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.) Commented Jul 18, 2018 at 6:35
  • Update: back to 10 seconds loading here on MSE, and looks like the index is missing on se.com? Commented Jul 19, 2018 at 14:47
  • @ShadowWizard Better now?
    – Taryn StaffMod
    Commented Jul 19, 2018 at 18:37
  • 2
    Yes! Awesome, saw your answer about se.com but what did you do here for MSE? Commented Jul 19, 2018 at 18:50
  • 1
    @ShadowWizard Same thing as this answer
    – Taryn StaffMod
    Commented Jul 19, 2018 at 18:52

You must log in to answer this question.

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