Sherlock Homepage - A detective story about running large web services
Balliauw, Maarten
The site was slow. CPU and memory usage everywhere! Some dead objects in the corner. Something terrible must have happened! We have some IIS logs. Some traces from a witness. But not enough to find out what was wrong. In this session, we’ll see how effective telemetry, a profiler or two as well as a refresher of how IIS runs our ASP.NET web applications can help solve this server murder mystery.
 All right. Good morning, everyone. Can everyone hear me? Awesome. Thank you. I was a little bit worried when I saw no one sitting in the middle, but it sort of explains itself because the screens are over there. So thank you. It's not because I smell, which is awesome after a couple of days of NDC. Welcome to this session, Sherlock Homepage. It's a big detective story about running large-scale services, and we'll see in a bit what that means, but first let's dive in. So on one good day last year, I think it was around April last year, we had an issue with our life sites. We were completely unavailable. Nothing was available. None of our customers could use our website. So what we were seeing was that our primary website location was just gone off the Internet. Nothing available. If we used our domain name, we could not hit our website, and nothing was visible there. So that was an issue. Now, the good thing is we are smart people, and of course we have a secondary location, and we have traffic manager in front, which is a DNS service that does failover in case the primary location goes down. So awesome. We thought we had fixed it. Problem was, when that failover happens, we found out that the secondary location was also unavailable. And you would think we would be as smart to have a third location, but unfortunately no. So we were completely gone off the Internet. So that's a big issue. Website down, our customers were complaining, Twitter was on fire, everyone was complaining that we had an issue. So we went on an initial investigation, so we got some monitoring alerts and stuff like that, and we started looking into what was happening there. And of course we saw that the website was unavailable from the Internet, but we did see that all the server instances in both the primary and secondary location were all available. If we hit the direct end points of each individual machine, we could reach the individual machine and just look at the website and do whatever we wanted there. The only thing was that traffic manager, so the DNS didn't work, we couldn't reach the websites. And if we would hit the load balancer end points that was in front of those web servers, we would also not hit the website. So either we had a DNS issue or the load balancer would have an issue. So we went to look and we found running on Azure that it actually was the load balancer causing a problem. So I don't know if you noticed, but if you run cloud services on Azure, you can actually instruct the load balancer to check your websites every couple of minutes to see if it's still available. By default, it just checks the root of your web URL, sees if a 200 OK comes back, and if that's OK, your machines are in the load balancer pool and they will get traffic. Now in our case, we had customized this and we had a custom internal API endpoint where we went to API slash status. And if that one didn't give back a 200 OK, then that machine would go out of the load balancer rotation and would become unavailable through the load balancer. Now the funny thing there was that eventually all the machines were going out of the load balancer because this endpoint was returning a non-successful status code, which meant the load balancer was there. The web servers were there, throwing 500 errors, but the load balancer would just take them out of rotation. And that happened on both locations, so primary location and secondary location, which meant we were just completely gone because all traffic would stop at the load balancer because the load balancer had nothing to serve traffic to. We found out in our codes of this status service, we found out that the root cause of this issue could be one of many services. This status endpoint internally checks if our REST APIs are available, if our SQL database is available, if our storage is available, if our search API is available, and if we could post statistics. So one of these services was probably down and because of that, this status endpoint was returning an error, which in turn would remove all the instances from the load balancer and just make us disappear from the face of the earth. So we solved it and we basically removed the load balancer probe so that all the machines would be back in business. And we started digging in. Now before we dig in, I do want to mention this one. I actually like the website highscalability.com very, very much because they have interesting topics on all the big companies like Twitter, like LinkedIn, on their architectures and stuff like that. And every now and then they have an insightful post and I especially like this one where they mentioned the book called Mindhunter, which is written by an FBI profiler who does investigations on serial killers and psychopaths and so on. And it's funny that hunting bugs in your codes and hunting issues in your code and your applications is quite similar to how those guys work. They try to bring their minds into how the system works into the bug or the psychopath in this case would be doing and why he would do that and what the approach would be to cause havoc and things like that. But the bottom line of this book is you have to know what it's like to be in the shoes of the psychopath or serial killer or in this case the bug or the issue in your system. Another nice quote in there is that you have to have a sympathy for the machine. You have to really think like the machine, think like your code, know your code, know whatever is happening and so on in your system. So that's a really important thing. And maybe you don't know your entire system completely. Imagine you're new on the job and you're tasked to investigate an issue like this, but you'll probably have done something similar in a previous job. So you take away all that experience to your next job and you get to know this type of distributed systems and how typically these architectures are built. So we had that knowledge. We had empathy for our system because yeah, our system was down and we were thinking like what could be the case that our system is down. And all that combined, we basically had a hunch thinking maybe it's the load balancer and because of that experience, we proved that it actually was the load balancer taking all the machines out of rotation. One nice quote in this book as well, which I don't have on the slides, is that bugs are like serial killers. If you put them in society and they are in the right circumstances, nothing will happen. They will just remain quiet and do nothing until at a given point the right circumstances are there and then they take action and they can take one action and then they can take the next one and maybe the next one until they get caught. And the same with bugs and that's the thing we are going to see in this story. We fix a bug and a new bug turns up and we basically kept on rolling there. So thank you. Welcome to Sherlock Homepage, a detective story about running large scale web services. I'm Martin Bajo. I work at Microsoft on the NuGet team. So you can imagine what this large web service could have been. You can also imagine last year, who would have shot me on the stage last year if I told them I was from the NuGet team? I would have shot myself. All right. Thank you. So you may have noticed in the past year that things have improved on the server side and that we did a lot of work and that's what this talk is going to be about. And there's a couple of nice things in there. But before we dive in there, I want to give you some history on how NuGet came about and how the services were built and what our architecture looked like last year around, yeah, I think March, April timeframe. So our site serves in case you don't know NuGet. We serve packages to all.NET developers in the world and with.NET core coming about, I think we are only going to see more traffic on NuGet than what we currently already have. On average, we are good for some 10 million requests per day on our compute nodes. We also have a lot of stuff in a static CDN type of approach where we don't have to have compute to serve requests, which is awesome because we can offload a lot of things from our dynamic servers, but still we have 10 million requests per day on that dynamic website. It was built four or five years ago. I still feel that it was built as a proof of concept, saying, okay, we have OData, which is awesome. We want to do this packaging thing, which everyone is doing. So let's maybe create a database, put a packages table in there, have storage where we can serve the packages, then slam OData on top, basically expose the SQL data over HTTP, and yeah, NuGet. So that was how it was built. Unfortunately, after a while, the team found out that those things were not the good approach. So there were some optimizations like the OData feed would not always go to the database. You would hijack some commonly used queries like package restores, for example, and move them to a different API internally. That said, last year we had some rough times at this time. I still know running around here at NDC, talking to some of the other speakers. I know Paul Stack was continuously bugging me like, hey, Martin, it's NuGet up. And I was like, yes, it is up right now, but maybe in an hour or not. So we had some rough times. So our architecture at the time was we had front-end servers in two regions, so two data center locations in Azure. And the front-end servers run MVC and OData. MVC for the website, if you go to NuGet.org and you register and you search for packages and stuff like that, that's the MVC site. We also had the WCFO data to serve the packages to all the clients like Visual Studio, NuGet.exe, and so on. That said, we have, of course, a SQL database in the back-ends to serve package metadata, download counts, and things like that, and those two communicate with one another. So this was the initial architecture that we had, which didn't really scale because everyone would hit the database continuously because the OData layer was a really thin layer on top of that SQL database. So we did some improvements. And the biggest improvement there was that we started using Lucene for search because we have a lot of searches. Like in Visual Studio, if you search for a package, that would be a search, and it would search pretty much the entire database if you would hit SQL. So we basically hijacked that type of request and put it on a search service that runs Lucene. Also, for package restores, if you search a package by ID inversion, which is like an ID lookup, we go to that search service which has a cache of this package, has that metadata, and lives at this URL so we can quickly serve your data. Now, of course, this thing has to have data as well. And we store our index and download counts, documents, and things like that on Azure Storage. But of course, we need that storage to be populated with data from the SQL database. So we have some job VM runners that basically do things like creating the index every couple of minutes, updating statistics if you download a package that you can see an increment in a download count or things like the download counts from the last six weeks and so on. That was the architecture. Now, did we solve the crime of this load balancer going RE? I don't think so. We solved the immediate danger where we were offline. We basically told the load balancer to not care about the status endpoint and still have the website up and running. But did we solve the crime? No. We still don't know what costs this load balancer probe to go RE. So one of our services cost this. SQL, storage, our search service, or our metric service. We have a check on the gallery service there as well. But because that is hosted on the same system, we are pretty confident that that was not the issue because it would, yeah, sort of, it's a redundant check. So one of these four services was actually acting up and we had to find out what was the cost of this issue. So what we did was locks-pulunking. You dive into the locks, you try and search clues on what went wrong and why the service was actually acting up. So the first thing we did was check some SQL database locks and we logged into the Azure portal and we wanted to see the locks and we found out we had none. That's been fixed, of course, but that was quite inconvenient at the time because we didn't have those locks. So we couldn't check the database if that one had been down at that moment in time or not. So we sort of knew the database may be yes, maybe no, that was the cost of the issue, but we couldn't say for sure because we had no locks of that one at the time. We looked into storage locks. On Azure, you can basically enable logging on storage and you can see which requests pass through what your error rate is and things like that and storage was healthy as a fish in the water. Nothing was wrong with storage. So definitely not storage, maybe SQL. We looked at search. We have some extensive logging on there as well, but we didn't see anything out of the ordinary there either. All 200 OKs coming back from search and nothing wrong there. We looked into our metric service. Also nothing wrong there. It's basically something that has been deployed, has been stable for months in a row, actually two years in a row where we didn't make any changes to the process and it just kept on working perfectly fine. So yeah, we still weren't the wiser and we started to look around at the crime scene. We started to put those little yellow markers of evidence on the VMs. So we logged into our Azure VMs and we started looking at IAS logs, event viewer logs and things like that. We did some profiling as well and yeah, I still have those traces with me. Well, most of the traces. I didn't keep them all, which is unfortunate, but I do have a couple. So one of the things we found on our gallery database was this trace, sorry on our gallery VMs. We did a trace and we got back this data. So there's a couple of things to note here. First of all, the CPU diagram looks quite healthy. It's not out of the ordinary. No excessive garbage collections happening or something like that. So actually the service looked quite well when this issue was happening. Another thing we saw was lock contention. No locks, no waiting for locks and things like that. There is quite some time spent waiting, but we found out that wait time was basically just because the service didn't get enough traffic and the CPU was idling because yeah, there's almost no traffic. What we did find out though was that the top called methods and I would like to zoom into the right. Okay, you'll have to believe me on my words or try to zoom in yourself. The top method we had was this hijack method. So that was the method called most in our search in our gallery server, which is the method that actually takes the OData query coming in, translates it to the REST API of our search service and then makes the call to the search service and fetches that data and returns it to the client. So that was the most called methods at that time. So we were like, hmm, so maybe it is search even though we didn't find anything on search. So we went on and we went into profiling the search service. I have those traces as well. And this looks a bit more problematic. You see CPU is quite okay, but garbage collection is crazy. This machine was doing 65% of work was it was doing garbage collection, which is insane. Another thing we found on search was lock contention. 16% of the time spent in our search service, it was waiting for locks to be freed. So we had lock statements in our codes and the code was just waiting for those to be freed again and to continue the work. Damn, that's too bad things. So lots of garbage collection and locks. Now, fun thing is if we filter on where are you waiting for locks, that is the moments where it's not garbage collecting. So we really had an issue there at the moment. So we went and we looked for what could be the cost of this lock statement and we found that our Lucene reloads method was actually waiting for a lock to be freed. That's not bad because the way Lucene works is it loads an index into memory so you can search through it. But before it has been loaded completely, you cannot search in that index because things would break down and crash. So Lucene has a lock statement in there. We had a lock statement around that code to wait until the index was loaded before serving traffic on that index. The one issue we had there, though, was the following. Of course, it was search. This looked really bad and we started looking into the code and we found in our searcher manager, by the way, we are open source. So if you look into those commits, you can actually see these things. We had a start reopen method in there. And that method would basically lock until the entire index was loaded into memory and we could do search on that. Now, this is not very problematic because it's how you want to work with Lucene. The moment where it starts to become problematic is when this is in your HTTP request path because that means all your users are waiting at that moment. And that was what was happening. We were basically blocking HTTP requests because the index wasn't loaded yet or refreshed completely yet and we had a lock statement in there. So we removed that one, refactored a little bit and found that it worked perfectly fine. Another thing we found in this profiling session was this excessive garbage collection. So I don't have the traces anymore, but we also did a memory profiling session there and we found out that this garbage collection was caused by excessive allocation of strings and J objects and dictionaries. Turns out when we serve traffic on our search service, we try to correlate the search query with the download count of the packages. So that packages with higher download counts in the past few weeks rank a little bit higher than packages with lower download counts. Now, to load those download counts because they continuously update, we don't want to write them into the index because the way it works is you write the document in the index and if you want to update the document, you actually have to delete and re-add the document. That causes a lot of churn and a lot of waiting, merging, things like that. So we don't want to do that. What we do is we have a blob in storage containing all these download counts. We load it as a JSON blob and we use that as a source of this data. Turns out that we had some nice code in there. Remember, we have around, I think, around eight or 900,000 packages right now and every couple of minutes, we would do this, load download counts into a dictionary of package ID, package version and the download count. Anyone see what's wrong with this code? There's nothing wrong with this code. There is something wrong with this code if you are loading 800,000 entries into these dictionaries and you reallocate the entire dictionary every five minutes. That's the problem here. Because we were doing that, the garbage collector would have to garbage collect every single entry in these dictionaries, recreate the dictionary and this was happening every five minutes. So every five minutes, this would happen. Garbage collection would take some time. Then we would hit our lock so we would wait some more time and then after five minutes, we would start this cycle again and again and again and this was why search was misbehaving. So what we did was we basically replaced this with a dictionary and we just update the values. If the package is already in the dictionary, we just update the download counts in the dictionary instead of recreating the entire dictionary with all its entries, reducing memory traffic and reducing garbage collection a lot. So that was what we did there. Case closed, awesome. We found out why we were down and what the issue was and happy times. Now remember when I said that bugs are like serial killers in society when given the right circumstances, they do something until you catch them. Well, we caught this bug but the circumstances changed by fixing this bug so it had a new opportunity. Before we dive into that, we did some things. So we found out we had no SQL logging at the time so we enabled those things. This was also the time when app insights came about on Azure and we started looking into that one. Not sure if you noticed this thing but I'm just going to quickly show you so you have an idea. App insights basically correlates your server response times, all your different performance counters and so on with HTTP requests so we can see which request is slowest. We can correlate it with the time, we can correlate it with which dependencies have been called like storage or SQL and so on. So it's basically a search engine for monitoring data and you can see whatever is happening there. If there's an exception, you can see the stack trace, things like that. So really useful tool to do some quick debugging. It's like a continuous mini profiler running in Azure and collecting all that data. So quite nice. So we did that. We added some more logging. App insights was introduced in all the different services and we thought happy times we can continue with our regular work. Now unfortunately, one of those days we had internal server errors on all our machines during package restores. So the thing is when you open up a new project and you build the project for the first time and Nuget packages haven't been downloaded yet, what Visual Studio does is restore those packages from our services but of course if we say internal server error at that time, people get no packages and people get mad and want to kill us. So that's what we were seeing. What we were seeing in App Insights this time was that of course a lot of internal server errors were happening. We saw that the response times went up while the number of requests actually went down. If we looked in event viewer and in the different views in App Insights, we saw that IIS was crashing on us on the machines themselves. Well actually on the log location we found a lot of crash dumps from IIS as well. So something was fishy here. IIS was crashing every couple of minutes. That's not good. So IIS crashes. What do you do to investigate? Well there's event viewer which tells you some things but in case you don't know, IIS is basically a fancy wrapper with additional things around HTTP.sys which is a kernel module in Windows that actually serves HTTP traffic. So IIS is just a fancy thing around HTTP.sys. Now IIS does logging but this HTTP.sys kernel module also does logging. So if on Azure you go into this spot in system 32 and actually on any IIS web server you can go there, you will find different logs that give you different information about connection states and so on. And what we saw in that log was a lot of entries saying connection abandoned by request queue. That's a nice error and if you search for it on Google, not on Bing because Bing sucks in Belgium where I live. It's actually quite nice in the US whenever I'm there. But we search for it and you cannot find any results on any of the popular search engines. You can find some information, some vague information on MSDN but somewhere we found that this error message means that a worker process from the application pool has quit unexpectedly or orphaned a pending request by closing its handle. So this basically means IIS gave up, we close the connection and see you next time. That's basically what the error was. So we knew something was happening, IIS was crashing, HTTP.sys was giving up on users. So we went to the gift of the gods which is crash dumps and we pulled those from the machines and we looked into that. Now if there are any hardcore debuggers in here you will probably look at me and say why aren't you not using WinDBG because WinDBG is quite complex and not the best demo. So that's why. But fortunately you can also open crash dumps in plain old Visual Studio and it's actually quite good. You get some information about the crash dump and you can see that the threat tried to read or write to a virtual address for which it doesn't have appropriate access, an exception. So this exception was the last thing recorded in this entire dump before IIS gave up. So this is probably the cause of IIS crashing. Now this error, if you search for it, you don't find a lot of useful information. You find lots of useful information like this can be why it crashes but still you get 100,000 results with every result actually being a different result telling something else about the cause of this error. So what you can do is there's actually a couple of nice windows as well in Visual Studio where you can look into the threats and states at that time in the application. But the fun thing is you can also debug a crash dump. So let's do that. Let's debug with managed only and you actually get the states of the machine at the moment this crash dump was taken and you can look into variables if you have a full dump. This is a mini dump so you only get stack traces. So we see this exception and it's the same exception we already saw if there's a hand, sorry, access violation, reading location, some number. Okay, let's break like you would do in a regular debugging session and you see there's no symbols. I'll cover that in a bit but we can also go hardcore and just view the disassembly and as you can see this move statement failed and that's why IS crashed. Any questions? No. So yeah, that's not very helpful this statement. You could go through the IL and there's actually a couple of guys within Microsoft who would go through the IL and just debug it from there but they are insane. We took the other approach which was finding the symbols for this code. Now we found out that our build server would not publish symbols anywhere and we found out that our retention policy on the build server had already deleted the symbols for this specific deployment of our service which meant we had no symbols and we could not correlate with whatever was happening at the time. Good thing there are some awesome tools available where you can just decompile whatever is happening. So thank you JetBrains for.peak. There's a couple of others as well but these guys have a symbol server built in which means you just open any assembly in there. If Visual Studio asks for symbols they decompile it and give you source code that is whatever was compiled at the moment. It's not the actual source code you get all the compiler optimizations and things like that but you do get a good view of where in your code this thing is actually crashing. So let's do that. Let's configure our symbol server. Let's enable that one. Disable just my code. Yes and then we should be able to load the symbols. Ha, there we are. Sources from.peak decompiled from our assembly for which we didn't have the code anymore. Where was this failing? In a task.run where we would post download statistics to our download service. So whenever you download a package we increment the number we save the header. Was this an install or a restore or an update for example? And the version of the Nuget client so we know when we can deprecate a specific version of the Nuget client for example. So this line was crashing. Now this line if we went into our codes wasn't that special. The only thing it would do is read some headers and post the number into some service somewhere. So yeah, not very helpful. It is helpful. We knew where in our code this was crashing but not why this was crashing. So an exception crashes IES. Well, yes, this was the actual code so the decompiler actually did a pretty good job of bringing that code into Visual Studio. So this was the actual code and our task.run post download statistics was actually failing. So what we did was search Google Bing search whatever search engine we could find and we didn't find anything useful about the exception that we were seeing in relation to HTTP requests and async await and tasks and things like that. Until at a given point in time I think after seven hours of searching that's all we did that day we found one guy who said well unobserved exceptions in a task that run can crash your process. Who knew this? I didn't know. So apparently whenever there's an exception happening in a piece of code that you are running inside a task that you are no longer observing which is what we do here. This is basically a fire and forget task that run. You know it will run eventually to post the download statistics. If there's an exception in this post download statistics code the task will crash but because no one is listening to the exception the process will crash. Damn. So how do you solve this? Well apparently you can tell the task scheduler that you want to attach an event handler to the unobserved task exception event and you can just do your logging there and just exit the method with set observed and then the exception is observed and is will no longer crash in this case. Reason for the crash by the way was that our HTTP request would fail from time to time. So if we couldn't post download statistics our frontend would go down because this task would throw. So we added these few lines of code, added some logging and we were happy again and case closed. Awesome. This was funny. That was a colleague of mine. Anyway. So the next thing we were seeing after we fixed this one was high response times on our server. We were seeing really high response times on people doing restores and installs on all the different packages. So what we were seeing was very high CPU usage, long response times. Azure would auto scale. We had auto scaling at the time adding more instances but basically what it would do was oh CPU is high add more instances. Those new instances would get high CPU and we would add more instances and basically spend our budget for the year. The profiler when we attached it also showed lots of wait times in there as well. So that was definitely an issue but what was the cause of that one? So we went to eating donuts again the parallel with profilers and so on. We basically sat down, thought what could be the case of this and did some searching and so on. And we found that there's a couple of possible causes for this issue. This one was actually what we were seeing. When IAS launches your application it will assign a couple of worker threads to the application to basically run things like HTTP requests running in the back and so on or reading from the database for example. And by default I think it's two threads that IAS starts per CPU or per logical CPU in your machine and it's automatically adds new threads whenever they are required to serve traffic or serve background tasks or whatever. The fun thing is that IAS and this is actually documented, if IAS gets burst loads like a lot of requests in a short time, the thread number doesn't scale up fast enough to cope with all that incoming traffic. So if you have a new machine and you have one user and then two and then three and then four in a reasonable amount of time, IAS will cope just fine. If all of a sudden your machine comes into the load balancer and there's a thousand people hitting that machine, it will probably start waiting for things to happen because it doesn't have enough background threads to do database and HTTP work and so on. So we went in there and we changed this setting in the IAS settings and this is what we saw. This was actually during NDC last year, I fixed this from the speaker room. Seriously, so that was funny. We saw in App Insights when we rolled out this change on all the different servers, the response times where they were really flaky before would just stabilize in a nice smooth flat line and in this case that's actually a good thing. Compared to the last week, you can see the graphs there as well from the last week in App Insights. This was really much, much, much better than what we had at the time. So case closed, I think. The only thing is we were running on cloud services so we had to automatically change this setting whenever the machine would boot. Luckily, you can add a startup script in there and do some tweaking when the machine starts up and basically what you do is call into IAS's command line tool and set the right sections in your applicationhost.config. That's what we did there. Case closed, but we were not there yet. How much time do I have left? Still a bit. We were seeing, the next thing we were seeing were package restore timeouts. So people doing restores were not getting high response times. Their response times were normal except for a few requests that would just never come back and timeout eventually. So what we were seeing on our V2-based Vits, which go through Compute, which is in Visual Studio no longer the case, or in Visual Studio 2015, we actually made an improvement with a new API that is served from static files on a CDN somewhere. But with our previous versions, the V2 feeds would go through Compute and would show lots of timeouts. These timeouts would not happen for a couple of hours. Then every seven to 15 hours, we would see this massive increase in response times, like extreme load times. You can see one get by ID taking one minute. It's insane. But it would fix itself as well. So after about 15 minutes, response times would drop again to a normal level. That's an interesting one to find out what is going on there. So there was no easy way to reproduce this. We tried reproducing the issue with the latest code we had deployed and so on on local machines. We were unable to reproduce it on our local machines or our dev environments, only happening on production. So what we had to do was find a way to troubleshoot this issue. We normally don't do this, but in this case, since it was only happening on production, we isolated one machine. We let traffic through to it, but didn't let it respond traffic to our end users. So we could see the traffic coming in and observe whatever was happening. What we did was we already peed in and in Task Manager, we saw 100% CPU usage, which is awesome and which was the issue we were seeing. But the problem with that is if you want to launch a profiler when your machine is at 100% CPU, the profiler adds even more overhead. You start swapping and doing process interchanges and so on. And yeah, you basically don't get a reliable result from that. So damn. So we sat down and started thinking and we thought, okay, what did we change last week and the thing we changed was this minIoTread setting in IS. In app insights, we could learn that the slow code path was find packages by ID. That was the only call that was being slow and we thought, okay, what does this call do? This call actually does an HTTP request to our search service to get back a result and to serve the package to your end user. And that was a slow call path. So these things seemed to correlate somehow. We had enough threads because we changed the setting, but our HTTP requests would probably cause this issue because that code path does not do anything else than just making an HTTP request and returning the response. So we started searching and we found out that when you are using HTTP clients in a.NET machine, that thing actually doesn't have a limit on the amount of requests it will make. So if you write a console application, fire up 32,000 threads on your machine and hit another machine with it, you will suffer TCP port exhaustion. All your ports are stuck because all, yeah, there's no additional traffic flowing over the line because everything is stuck at the OS level. So we started thinking, okay, HTTP client is doing this nice, but that can be an issue because you have a lot of TCP ports in a machine. So we read up on TCP IP a little bit more and we found out that by default on Windows, whenever a connection is closed, the OS actually holds on to the TCP port for about four minutes before it freezes because there may still be traffic coming in, a load balancer may be acting up or whatever. Some packets may still come in related to this connection and that's why Windows says, okay, I'm not freeing this one for reuse yet because whenever something comes in, I want to basically ignore it and not confuse whoever is reusing this TCP port. And after four minutes, it's free the port and you can use it again. Now, fun thing there is that for each fine packages by ID, which is our package restore part, we would make an outgoing HTTP request, one port, but the user would also come in and ask us for that restore. That's two ports. Lots of restores happening. Four minute wait time in Windows. So basically what we were seeing was that we had TCP port exhaustion and everything was waiting for Windows to free up those ports. After reading up some more, we found out that you can actually block the HTTP client from showing this behavior by setting your service point manager dot default connection limits to a reasonable value. So if you change that, HTTP client will actually adhere to those settings and if you set it to, for example, 500, it will only do 500 concurrent outgoing requests from your machines. So that's what we did. We changed the codes and we did some other optimizations there as well. Well, of course, the default connection limit is one we did. We didn't want to have TCP port exhaustion by just calling into our backend service. So we fixed that. But we also disabled Nagling at the time. I'm not sure if you're familiar with what Nagling is. Basically, the TCP IP protocol has an optimization where you have a certain package, packet size, which can contain data if you make an outbound request or an incoming request. And if you have small requests, TCP IP protocol will try to bundle those requests into as few packages, packets as possible to not saturate your network connection and things like that and make things appear more smoothly and more fast. Thing was our traffic was really small because we just fetched PID from the search service. So actually Nagling was working against us as well. So we disabled it and had smaller packets flowing across the wire there. So both optimizations were enabled and our issue was gone. Awesome. Some charts. The response time dropped from one minute to three seconds. I think that was still during the flighting period where we just patched some servers. And after that, response times dropped to a normal level at the time. So awesome. Case closed again. How much time do I have left? 20 minutes. All right. There's more. Unfortunately. What we were seeing. So we did all these optimizations and we followed this entire part of finding a bug, quashing the bug and then hitting a new bug. So what we were seeing was 100% memory usage on our medium Azure instances that we were running the service on. Okay. Scale up. Bigger machines. Happy times. Everything fine until two or three minutes after deployment. 100% memory usage. You were like, hmm, okay. Nice. This was the moment where ASP.net said they were going to do ASP.net next and we were seeing a lot of new users coming in and so on. So we thought, okay, maybe we just have a lot of new users coming on. Maybe we need just another bigger machine. So we did another upgrade. Two minutes in. 100% memory usage. If at that point you don't realize there's an issue, then yeah, you can just keep on spending and spending, but you will see the same thing on even bigger machines as well. So what do you do? You start analyzing memory on the servers. What can you do to do this on the server itself, which we don't like doing? So what we tried to do was reproduce the issue on our local machines and that's what we did. So the way we did it is we basically fetched a number of logs from our, where is my code? Where's my, there it is. Okay. So we fetched a number of logs from our server, IS logs, which are typical standards logging system and we downloaded a tool called JMeter. And JMeter is a Java-based tool which allows you to do things like load testing and so on. Nice thing about JMeter is that on high DPI screens, the UI is really, really small. But apart from that, it's actually a really cool tool because you can do things like replaying traffic. Let's open my test plan. It is as small for me as it is for you. Let's go in. Come on. Where did I put this document? There it is. We basically configured a test plan which would read our access logs from IS. So you basically tell this is my access log. You can read it from this specific path. Replay it against this server and then you can give it things like the number of users that you want to run against it, how you want to ramp up the number of users and so on. So to really reproduce the traffic your servers were seeing at a given time. So what we did was we looked into the logging. We decided on the window of the logs that we needed to replay this issue on our local machines and our dev environments and that's what we did. So thank you, JMeter for that. Your UI sucks but the tool is really, really awesome. So we did that and we went into the memory. Now, who of you would say they are really familiar with.NET memory management? Nobody? Good because I think nobody really is, not even the guys who wrote this thing. But I'll give you a quick introduction on how.NET memory management works so that you understand the problem we were seeing afterwards. So you replay the traffic but before we look at the results there's a couple of things you have to know. So in.NET as opposed to languages like C++ and so on, in.NET there's actually a run time, a managed run time that allocates memory for you if you need memory. In C++ what do you do? You tell the OS I need memory, they give you back an address in memory where you can store your stuff and if you don't free it you will get an out of memory situation because nobody is freeing up the memory for you. You have to really take care of that yourself. The way.NET works is whenever your application starts the run time asks the OS can you please allocate a big block of memory for me and I'll then in that block manage my own memory for you. So that's what.NET does and that big block of memory is the managed heap that you sometimes read about. Whenever you will instantiate a new object in.NET it gets allocated in this managed heap and that's really fast because you don't have to wait for the OS to give you access to a certain address..NET can basically tell you okay here's memory because it already has the memory available. Of course some unmanaged memory is also consumed like if you write a UI based application, WinForms or XAML or whatever you also get things like graphics buffers and things like that which are still unmanaged but most of the memory you are consuming in your.NET applications is this big chunk of data to manage to heap. Now whenever your variable goes out of scope and it's no longer needed you don't have to go and tell the OS to basically free the memory up again..NET will manage this for you. It will notice that the variable is out of scope. It will ignore that fact because it still has a big chunk of memory available so it will not free the memory immediately. What it will do is at a given point in time it will run the garbage collector. The garbage collector basically what it does is it scans this entire block of memory searches for variables that are no longer being used and then removes those from the managed block of memory so that the memory can be reused in future times. Now I said it scans the entire block of memory and that's quite an expensive operation to do. That's why.NET came up, well actually a lot of managed languages came up with the concept of generations in this garbage collector. Basically when you create a new variable or instantiate a new object or whatever the memory for that is allocated in Gen0 as it's called. Gen0 is where short lift objects go. Like in a method you create a string and two lines beyond that your method goes out of scope. Well that's Gen0 and it can be reclaimed really really fast because.NET knows that probably all the things in there or a lot of the things in there will probably be out of scope and can be recycled anyway. Except for the objects that cannot be recycled. Those are moved into Gen1. Gen1 is where medium lift objects live in.NET and.NET keeps them around until they are no longer needed in there as well. So the garbage collector mostly runs on Gen0. Every once in a while it runs on Gen1 to free the objects in there and if an object survives Gen1 it's moved into Gen2. So the really long lift objects. If we think back to our download counts example where we had this big dictionary of strings that were package IDs, inversions and download counts. That thing would probably be either Gen2 or the large memory heap because that's a long lift object. It lives the entire application lifetime and never gets to get recycled by the garbage collector. So that's basically how.NET works. It has these generations of memory and it frees the memory up for Gen0 mostly. Then every once in a while it does Gen1 as well and then even fewer times it does Gen2. Reason for that is if you have a long lift object there's no use in scanning this entire part of memory to free up memory because it's probably still in use. So that's how it works. So visually you first have your object in Gen0 then it moves to Gen1 if it's still alive. If not it's being reclaimed and memory is freed. If in Gen1 your object lives on it will go to Gen2. If not it will go out of Gen2. In Gen2 same thing if it keeps on being alive it will just remain in Gen2 until future collections. If it can be freed it will be freed eventually. Then there's another special case in this managed heap which is the large object heap. This is where large objects go. If you have an object of more than 85 kilobytes in memory size it goes into the large object heap because.NET thinks it's going to take a while to scan this entire object and make sure that I can reclaim it during a garbage collection cycle. It basically puts it there and that's where things don't have to end up ideally. But they go there. One issue with the large object heap there is if you have a lot of objects in there there's not a lot of optimization going on there by default which means that if you have a lot of objects in there you get fragmentation and you will get eventually out of memory exceptions. All right. Almost there. The.NET garbage collector is actually a really nice thing because to your application it looks like you have an infinite amount of memory. You just create new variables, create new objects, create whatever you want to create in your memory..NET will handle the memory for you and make sure there's always some memory available to do new things and your application doesn't have to care about what's happening in there. Now when does this garbage collector run? That's actually not really well documented. There's a couple of documents describing a lot of things but I don't think everything is documented. Since.NET Core, the garbage collector is actually open source so you can look in the sources but I think last time I checked it's a massive, I think it's around 37,000 lines of code doing the memory management. So if you can go in there and find out when the garbage collector runs please tell me. I would like to know. But from observation most people say okay it happens when there's an out of memory condition. When no memory is available in the managed heap, garbage collector will run and try to free up some resources in memory. After a significant allocation, again our download counts if we would allocate a new dictionary and populate this entire dictionary with 800,000 entries, we were seeing garbage collection there. Even in our profiler we were seeing garbage collection because of that. Also when it fails allocating resources it thinks okay maybe there's a memory issue here, let's optimize this. When you have a profiler attached or when you force it to do a garbage collection or when your application moves to the background. But the most important thing from all these observations is that the garbage collector is not guaranteed to run. If you have enough memory available for example it will run fewer times or maybe not run at all. Interesting, keep that in mind. Let's analyze our memory usage. So we replay traffic on our production instances and we got a memory snapshot. This is what we got. The gray part is the unmanaged memory that's being used. The green part, sorry the blue part is gen 0, the red part is gen 1 and the green part is gen 2. So what we can see in this diagram is actually quite interesting because we can see gen 2 is growing continuously. That's one thing. That's not ideal to be honest. What we can also see is that every time we take a snapshot in memory, memory pressure drops and we get some memory back so some garbage collection is happening which is a good thing. So let's dive into one of our snapshots and see what was in memory at that time. Now I'm going to take snapshot 6 and I'm going to take it for some reason. This is the reason. 2 million objects basically have been removed from memory when I took this snapshot which means the garbage collector did its work and what I will be able to see in this snapshot is probably what the garbage collector didn't collect and that's what we were interested in. So let's open this snapshot and wait until that memory shows us the things. It's actually a nice tool because it shows you some of the most common memory issues that you can have like duplicate strings or event handlers that you don't dispose of correctly and so on and you can dive into whatever is in there. At the bottom we can see the heaps and as I already said on the big chart we were seeing gen 2 was growing and growing and growing so let's see what's in gen 2. We can go in there and see which objects are in there and by default it will sort the objects by the number of retained bytes and that's basically the amount of bytes this object holds on to in other objects and this object is an inject.activation.caching.cache. Okay nice I cannot zoom there. I'll tell you there's one object of those which sort of speaks for itself with a cache. You have one cache holding on to a number of objects. The cache itself is only 48 bytes so nothing wrong there and it's keeping on or holding on to 90 megabytes of objects. Could be good, could be bad. So let's dive in. What's in this object? We see that it has some entries and these entries are an array that contain keys and values and items and it's basically easy to really get lost in this entire tree so that's not really useful information. So let's take one step back and look at this entire list one more time. Another object we see here is this guy. Of course there's a number of collections and things like that in our memory as well but what's interesting is that our entity framework context shows up as the sixth biggest object held in memory in this trace. Hmm fishy. Especially since it's in gen 2 because I would expect if I serve requests that have to make database calls we open an entity framework context, we handle the request, we close the entity framework context and it gets garbage collected in gen 0 or the latest in gen 1. Not in gen 2. What's even more interesting is that it's almost 80 megabytes of entity framework contexts floating around in memory. Fishy. So let's go in there. We see that there's a number of objects of this entity framework context. Let's group them by similar retention. Basically look at who is keeping this entity framework context in memory. What's the reason why this thing has not been garbage collected? Who is keeping this in memory? And the interesting thing is that we see our NINJECT cache showing up as the object holding on to our entity framework context. In fact it's holding on to 532 entity framework contexts in our gen 2 heap. Hmm. Alright. So our DI container, NINJECT at the time, seemed to be the reason why we had a lot of entity framework contexts still floating around in memory. So we decided, since NINJECT is open source, to go through the codes and see if we could find what was happening and why this was still being held in memory. And we found this garbage collection cache pruner. It was kept in memory by the cache and we find this cache pruner. So let's look at the code in there. It has, let me zoom in a little bit. Oh, that's fast. So fast. We live in the golden age of CPU cycles and this is still so fast. Anyway, this garbage collection cache pruner would actually make sure that our cache of objects that we instantiate through our DI container is every once in a while being cleaned up and the object it holds on to are being garbage collected. The way it does that is it has a weak reference and a weak reference is a type of object. If you instantiate it and the garbage collector runs, it will basically remove the reference so you know something has happened to it and someone has recycled this object so you know a garbage collection happens. It has a list of caches. It has a timer and a thread pool timer. Now, the interesting thing is whenever the timer runs, which is every, I think, 30 seconds it was by default, it would purge prune cache if garbage collector has run. Okay, let's go there. Prune cache if garbage collector has run. If you are on a PCL, you are unlucky. If not, we would lock. We would check if our indicator, our weak reference has been collected or not. If it hasn't been collected, we just return and don't clear our cache. Okay, remember that the garbage collector is not guaranteed to run? That's the reason this variable was not collected and that's the reason why this timer would eventually just return every single time and just keep all the objects that it caches in its internal cache floating around and basically exhaust our memory continuously. So, yeah, Ninject was not very friendly to us and we found some other people with exactly the same issue and no fix yet. So, the thing we did was we changed to a different TI container, autofack in this case. We ran the new analysis and we saw that response times dropped tremendously, first of all. So, it was faster than Ninject as well and our memory issue was also gone and we are now stable at a 4 gigabytes memory usage overall on our compute nodes there. So, that's really, really nice improvement. Case closed. So, in conclusion, when you start debugging and when you start spelunking an entire chain of possible bugs that follow one after another, you will have to build some familiarity with your system that you are trying to debug and trying to investigate. Try to, in your mind, think like the compiler, think like.NET's garbage collector, think like whatever can happen in your own codes and that will really help you finding these issues. Bugs hides and we found out that whenever we fixed a bug, there would be a new bug popping up because we fixed the original bug and we would just open the floodgates to the new one. So, keep that in mind if you fix this type of issues, you may run into the next one the next day or even the next hour. What I did learn from this experience, I've been doing this for three, four months, this entire thing, what I did learn is that I learned a lot about how.NET works and I learned that I actually like spelunking through memory traces, through performance, snapshot sense and so on because you learn how your code is behaving even better, you learn how the.NET framework is behaving in the different versions of the.NET framework and you overall build experience for the next bug that comes along. So, if you have an issue like this, don't go, it's an ops problem, dive in and try and investigate, it's really, really useful to do. With that, thank you for being here and enjoy the rest of NDC.
 All right. Good morning, everyone. Can everyone hear me? Awesome. Thank you. I was a little  bit worried when I saw no one sitting in the middle, but it sort of explains itself because  the screens are over there. So thank you. It's not because I smell, which is awesome  after a couple of days of NDC. Welcome to this session, Sherlock Homepage. It's a big  detective story about running large-scale services, and we'll see in a bit what that  means, but first let's dive in. So on one good day last year, I think it was around  April last year, we had an issue with our life sites. We were completely unavailable.  Nothing was available. None of our customers could use our website. So what we were seeing  was that our primary website location was just gone off the Internet. Nothing available.  If we used our domain name, we could not hit our website, and nothing was visible there.  So that was an issue. Now, the good thing is we are smart people, and of course we have  a secondary location, and we have traffic manager in front, which is a DNS service that  does failover in case the primary location goes down. So awesome. We thought we had fixed  it. Problem was, when that failover happens, we found out that the secondary location was  also unavailable. And you would think we would be as smart to have a third location, but unfortunately  no. So we were completely gone off the Internet. So that's a big issue. Website down, our customers  were complaining, Twitter was on fire, everyone was complaining that we had an issue.  So we went on an initial investigation, so we got some monitoring alerts and stuff like  that, and we started looking into what was happening there. And of course we saw that  the website was unavailable from the Internet, but we did see that all the server instances  in both the primary and secondary location were all available. If we hit the direct end  points of each individual machine, we could reach the individual machine and just look  at the website and do whatever we wanted there. The only thing was that traffic manager, so  the DNS didn't work, we couldn't reach the websites. And if we would hit the load balancer  end points that was in front of those web servers, we would also not hit the website.  So either we had a DNS issue or the load balancer would have an issue. So we went to look and  we found running on Azure that it actually was the load balancer causing a problem. So  I don't know if you noticed, but if you run cloud services on Azure, you can actually  instruct the load balancer to check your websites every couple of minutes to see if it's still  available. By default, it just checks the root of your web URL, sees if a 200 OK comes back,  and if that's OK, your machines are in the load balancer pool and they will get traffic.  Now in our case, we had customized this and we had a custom internal API endpoint where  we went to API slash status. And if that one didn't give back a 200 OK, then that machine  would go out of the load balancer rotation and would become unavailable through the load  balancer. Now the funny thing there was that eventually all the machines were going out  of the load balancer because this endpoint was returning a non-successful status code,  which meant the load balancer was there. The web servers were there, throwing 500 errors,  but the load balancer would just take them out of rotation. And that happened on both  locations, so primary location and secondary location, which meant we were just completely  gone because all traffic would stop at the load balancer because the load balancer had  nothing to serve traffic to. We found out in our codes of this status service, we found  out that the root cause of this issue could be one of many services. This status endpoint  internally checks if our REST APIs are available, if our SQL database is available, if our  storage is available, if our search API is available, and if we could post statistics.  So one of these services was probably down and because of that, this status endpoint  was returning an error, which in turn would remove all the instances from the load balancer  and just make us disappear from the face of the earth. So we solved it and we basically  removed the load balancer probe so that all the machines would be back in business. And  we started digging in. Now before we dig in, I do want to mention this one. I actually  like the website highscalability.com very, very much because they have interesting topics  on all the big companies like Twitter, like LinkedIn, on their architectures and stuff  like that. And every now and then they have an insightful post and I especially like this  one where they mentioned the book called Mindhunter, which is written by an FBI profiler who does  investigations on serial killers and psychopaths and so on. And it's funny that hunting bugs  in your codes and hunting issues in your code and your applications is quite similar to  how those guys work. They try to bring their minds into how the system works into the bug  or the psychopath in this case would be doing and why he would do that and what the approach  would be to cause havoc and things like that. But the bottom line of this book is you have  to know what it's like to be in the shoes of the psychopath or serial killer or in this  case the bug or the issue in your system. Another nice quote in there is that you have  to have a sympathy for the machine. You have to really think like the machine, think like  your code, know your code, know whatever is happening and so on in your system. So that's  a really important thing. And maybe you don't know your entire system completely. Imagine  you're new on the job and you're tasked to investigate an issue like this, but you'll  probably have done something similar in a previous job. So you take away all that experience  to your next job and you get to know this type of distributed systems and how typically  these architectures are built. So we had that knowledge. We had empathy for our system because  yeah, our system was down and we were thinking like what could be the case that our system  is down. And all that combined, we basically had a hunch thinking maybe it's the load balancer  and because of that experience, we proved that it actually was the load balancer taking  all the machines out of rotation. One nice quote in this book as well, which I don't  have on the slides, is that bugs are like serial killers. If you put them in society  and they are in the right circumstances, nothing will happen. They will just remain quiet and  do nothing until at a given point the right circumstances are there and then they take  action and they can take one action and then they can take the next one and maybe the next  one until they get caught. And the same with bugs and that's the thing we are going to  see in this story. We fix a bug and a new bug turns up and we basically kept on rolling  there. So thank you. Welcome to Sherlock Homepage, a detective story about running large scale  web services. I'm Martin Bajo. I work at Microsoft on the NuGet team. So you can imagine what  this large web service could have been. You can also imagine last year, who would have  shot me on the stage last year if I told them I was from the NuGet team? I would have shot  myself. All right. Thank you. So you may have noticed in the past year that things have  improved on the server side and that we did a lot of work and that's what this talk is  going to be about. And there's a couple of nice things in there. But before we dive in  there, I want to give you some history on how NuGet came about and how the services were  built and what our architecture looked like last year around, yeah, I think March, April  timeframe. So our site serves in case you don't know NuGet. We serve packages to all .NET developers in the world and with.NET core coming about, I think we are only going  to see more traffic on NuGet than what we currently already have. On average, we are  good for some 10 million requests per day on our compute nodes. We also have a lot of  stuff in a static CDN type of approach where we don't have to have compute to serve requests,  which is awesome because we can offload a lot of things from our dynamic servers, but  still we have 10 million requests per day on that dynamic website. It was built four  or five years ago. I still feel that it was built as a proof of concept, saying, okay,  we have OData, which is awesome. We want to do this packaging thing, which everyone is  doing. So let's maybe create a database, put a packages table in there, have storage where  we can serve the packages, then slam OData on top, basically expose the SQL data over  HTTP, and yeah, NuGet. So that was how it was built. Unfortunately, after a while, the  team found out that those things were not the good approach. So there were some optimizations  like the OData feed would not always go to the database. You would hijack some commonly  used queries like package restores, for example, and move them to a different API internally.  That said, last year we had some rough times at this time. I still know running around  here at NDC, talking to some of the other speakers. I know Paul Stack was continuously  bugging me like, hey, Martin, it's NuGet up. And I was like, yes, it is up right now, but  maybe in an hour or not. So we had some rough times. So our architecture at the time was  we had front-end servers in two regions, so two data center locations in Azure. And the  front-end servers run MVC and OData. MVC for the website, if you go to NuGet.org and  you register and you search for packages and stuff like that, that's the MVC site. We also  had the WCFO data to serve the packages to all the clients like Visual Studio, NuGet.exe,  and so on. That said, we have, of course, a SQL database in the back-ends to serve package  metadata, download counts, and things like that, and those two communicate with one another.  So this was the initial architecture that we had, which didn't really scale because  everyone would hit the database continuously because the OData layer was a really thin  layer on top of that SQL database. So we did some improvements. And the biggest improvement  there was that we started using Lucene for search because we have a lot of searches. Like  in Visual Studio, if you search for a package, that would be a search, and it would search  pretty much the entire database if you would hit SQL. So we basically hijacked that type  of request and put it on a search service that runs Lucene. Also, for package restores,  if you search a package by ID inversion, which is like an ID lookup, we go to that search  service which has a cache of this package, has that metadata, and lives at this URL so  we can quickly serve your data. Now, of course, this thing has to have data as well. And we  store our index and download counts, documents, and things like that on Azure Storage. But  of course, we need that storage to be populated with data from the SQL database. So we have  some job VM runners that basically do things like creating the index every couple of minutes,  updating statistics if you download a package that you can see an increment in a download  count or things like the download counts from the last six weeks and so on. That was the  architecture. Now, did we solve the crime of this load balancer going RE? I don't think  so. We solved the immediate danger where we were offline. We basically told the load balancer  to not care about the status endpoint and still have the website up and running. But  did we solve the crime? No. We still don't know what costs this load balancer probe  to go RE. So one of our services cost this. SQL, storage, our search service, or our metric  service. We have a check on the gallery service there as well. But because that is hosted  on the same system, we are pretty confident that that was not the issue because it would,  yeah, sort of, it's a redundant check. So one of these four services was actually acting  up and we had to find out what was the cost of this issue. So what we did was locks-pulunking.  You dive into the locks, you try and search clues on what went wrong and why the service  was actually acting up. So the first thing we did was check some SQL database locks and  we logged into the Azure portal and we wanted to see the locks and we found out we had none.  That's been fixed, of course, but that was quite inconvenient at the time because we  didn't have those locks. So we couldn't check the database if that one had been down at  that moment in time or not. So we sort of knew the database may be yes, maybe no, that  was the cost of the issue, but we couldn't say for sure because we had no locks of that  one at the time. We looked into storage locks. On Azure, you can basically enable logging  on storage and you can see which requests pass through what your error rate is and things  like that and storage was healthy as a fish in the water. Nothing was wrong with storage.  So definitely not storage, maybe SQL. We looked at search. We have some extensive logging  on there as well, but we didn't see anything out of the ordinary there either. All 200  OKs coming back from search and nothing wrong there. We looked into our metric service.  Also nothing wrong there. It's basically something that has been deployed, has been stable for  months in a row, actually two years in a row where we didn't make any changes to the process  and it just kept on working perfectly fine. So yeah, we still weren't the wiser and we  started to look around at the crime scene. We started to put those little yellow markers  of evidence on the VMs. So we logged into our Azure VMs and we started looking at IAS  logs, event viewer logs and things like that. We did some profiling as well and yeah, I  still have those traces with me. Well, most of the traces. I didn't keep them all, which  is unfortunate, but I do have a couple. So one of the things we found on our gallery  database was this trace, sorry on our gallery VMs. We did a trace and we got back this data.  So there's a couple of things to note here. First of all, the CPU diagram looks quite  healthy. It's not out of the ordinary. No excessive garbage collections happening or  something like that. So actually the service looked quite well when this issue was happening.  Another thing we saw was lock contention. No locks, no waiting for locks and things like  that. There is quite some time spent waiting, but we found out that wait time was basically  just because the service didn't get enough traffic and the CPU was idling because yeah,  there's almost no traffic. What we did find out though was that the top called methods  and I would like to zoom into the right. Okay, you'll have to believe me on my words or try  to zoom in yourself. The top method we had was this hijack method. So that was the method  called most in our search in our gallery server, which is the method that actually takes the  OData query coming in, translates it to the REST API of our search service and then makes  the call to the search service and fetches that data and returns it to the client. So  that was the most called methods at that time. So we were like, hmm, so maybe it is search  even though we didn't find anything on search. So we went on and we went into profiling the  search service. I have those traces as well. And this looks a bit more problematic. You  see CPU is quite okay, but garbage collection is crazy. This machine was doing 65% of work  was it was doing garbage collection, which is insane. Another thing we found on search  was lock contention. 16% of the time spent in our search service, it was waiting for  locks to be freed. So we had lock statements in our codes and the code was just waiting  for those to be freed again and to continue the work. Damn, that's too bad things. So  lots of garbage collection and locks. Now, fun thing is if we filter on where are you  waiting for locks, that is the moments where it's not garbage collecting. So we really had  an issue there at the moment. So we went and we looked for what could be the cost of this  lock statement and we found that our Lucene reloads method was actually waiting for a  lock to be freed. That's not bad because the way Lucene works is it loads an index into  memory so you can search through it. But before it has been loaded completely, you cannot  search in that index because things would break down and crash. So Lucene has a lock  statement in there. We had a lock statement around that code to wait until the index was  loaded before serving traffic on that index. The one issue we had there, though, was the  following. Of course, it was search. This looked really bad and we started looking into the  code and we found in our searcher manager, by the way, we are open source. So if you  look into those commits, you can actually see these things. We had a start reopen method  in there. And that method would basically lock until the entire index was loaded into  memory and we could do search on that. Now, this is not very problematic because it's  how you want to work with Lucene. The moment where it starts to become problematic is when  this is in your HTTP request path because that means all your users are waiting at that  moment. And that was what was happening. We were basically blocking HTTP requests because  the index wasn't loaded yet or refreshed completely yet and we had a lock statement in there.  So we removed that one, refactored a little bit and found that it worked perfectly fine.  Another thing we found in this profiling session was this excessive garbage collection. So  I don't have the traces anymore, but we also did a memory profiling session there and we  found out that this garbage collection was caused by excessive allocation of strings  and J objects and dictionaries. Turns out when we serve traffic on our search service,  we try to correlate the search query with the download count of the packages. So that packages  with higher download counts in the past few weeks rank a little bit higher than packages  with lower download counts. Now, to load those download counts because they continuously  update, we don't want to write them into the index because the way it works is you write  the document in the index and if you want to update the document, you actually have  to delete and re-add the document. That causes a lot of churn and a lot of waiting, merging,  things like that. So we don't want to do that. What we do is we have a blob in storage containing  all these download counts. We load it as a JSON blob and we use that as a source of this  data. Turns out that we had some nice code in there. Remember, we have around, I think,  around eight or 900,000 packages right now and every couple of minutes, we would do this,  load download counts into a dictionary of package ID, package version and the download  count. Anyone see what's wrong with this code? There's nothing wrong with this code. There  is something wrong with this code if you are loading 800,000 entries into these dictionaries  and you reallocate the entire dictionary every five minutes. That's the problem here. Because  we were doing that, the garbage collector would have to garbage collect every single  entry in these dictionaries, recreate the dictionary and this was happening every five  minutes. So every five minutes, this would happen. Garbage collection would take some  time. Then we would hit our lock so we would wait some more time and then after five minutes,  we would start this cycle again and again and again and this was why search was misbehaving.  So what we did was we basically replaced this with a dictionary and we just update the values.  If the package is already in the dictionary, we just update the download counts in the dictionary  instead of recreating the entire dictionary with all its entries, reducing memory traffic  and reducing garbage collection a lot. So that was what we did there. Case closed, awesome.  We found out why we were down and what the issue was and happy times. Now remember when  I said that bugs are like serial killers in society when given the right circumstances,  they do something until you catch them. Well, we caught this bug but the circumstances changed  by fixing this bug so it had a new opportunity. Before we dive into that, we did some things.  So we found out we had no SQL logging at the time so we enabled those things. This was  also the time when app insights came about on Azure and we started looking into that  one. Not sure if you noticed this thing but I'm just going to quickly show you so you  have an idea. App insights basically correlates your server response times, all your different  performance counters and so on with HTTP requests so we can see which request is slowest. We  can correlate it with the time, we can correlate it with which dependencies have been called  like storage or SQL and so on. So it's basically a search engine for monitoring data and you  can see whatever is happening there. If there's an exception, you can see the stack trace,  things like that. So really useful tool to do some quick debugging. It's like a continuous  mini profiler running in Azure and collecting all that data. So quite nice. So we did that.  We added some more logging. App insights was introduced in all the different services  and we thought happy times we can continue with our regular work. Now unfortunately,  one of those days we had internal server errors on all our machines during package restores.  So the thing is when you open up a new project and you build the project for the first time  and Nuget packages haven't been downloaded yet, what Visual Studio does is restore those  packages from our services but of course if we say internal server error at that time,  people get no packages and people get mad and want to kill us. So that's what we were  seeing. What we were seeing in App Insights this time was that of course a lot of internal  server errors were happening. We saw that the response times went up while the number  of requests actually went down. If we looked in event viewer and in the different views  in App Insights, we saw that IIS was crashing on us on the machines themselves. Well actually  on the log location we found a lot of crash dumps from IIS as well. So something was fishy  here. IIS was crashing every couple of minutes. That's not good. So IIS crashes. What do you  do to investigate? Well there's event viewer which tells you some things but in case you  don't know, IIS is basically a fancy wrapper with additional things around HTTP.sys which  is a kernel module in Windows that actually serves HTTP traffic. So IIS is just a fancy  thing around HTTP.sys. Now IIS does logging but this HTTP.sys kernel module also does  logging. So if on Azure you go into this spot in system 32 and actually on any IIS web server  you can go there, you will find different logs that give you different information about  connection states and so on. And what we saw in that log was a lot of entries saying connection  abandoned by request queue. That's a nice error and if you search for it on Google,  not on Bing because Bing sucks in Belgium where I live. It's actually quite nice in  the US whenever I'm there. But we search for it and you cannot find any results on any  of the popular search engines. You can find some information, some vague information on  MSDN but somewhere we found that this error message means that a worker process from the  application pool has quit unexpectedly or orphaned a pending request by closing its  handle. So this basically means IIS gave up, we close the connection and see you next time.  That's basically what the error was. So we knew something was happening, IIS was crashing,  HTTP.sys was giving up on users. So we went to the gift of the gods which is crash dumps  and we pulled those from the machines and we looked into that. Now if there are any  hardcore debuggers in here you will probably look at me and say why aren't you not using  WinDBG because WinDBG is quite complex and not the best demo. So that's why. But fortunately  you can also open crash dumps in plain old Visual Studio and it's actually quite good.  You get some information about the crash dump and you can see that the threat tried to read  or write to a virtual address for which it doesn't have appropriate access, an exception.  So this exception was the last thing recorded in this entire dump before IIS gave up. So  this is probably the cause of IIS crashing. Now this error, if you search for it, you  don't find a lot of useful information. You find lots of useful information like this  can be why it crashes but still you get 100,000 results with every result actually being a  different result telling something else about the cause of this error. So what you can do  is there's actually a couple of nice windows as well in Visual Studio where you can look  into the threats and states at that time in the application. But the fun thing is you  can also debug a crash dump. So let's do that. Let's debug with managed only and you actually  get the states of the machine at the moment this crash dump was taken and you can look  into variables if you have a full dump. This is a mini dump so you only get stack traces.  So we see this exception and it's the same exception we already saw if there's a hand,  sorry, access violation, reading location, some number. Okay, let's break like you would  do in a regular debugging session and you see there's no symbols. I'll cover that in  a bit but we can also go hardcore and just view the disassembly and as you can see this  move statement failed and that's why IS crashed. Any questions? No. So yeah, that's not very  helpful this statement. You could go through the IL and there's actually a couple of guys  within Microsoft who would go through the IL and just debug it from there but they are  insane. We took the other approach which was finding the symbols for this code. Now we  found out that our build server would not publish symbols anywhere and we found out  that our retention policy on the build server had already deleted the symbols for this specific  deployment of our service which meant we had no symbols and we could not correlate with  whatever was happening at the time. Good thing there are some awesome tools available where  you can just decompile whatever is happening. So thank you JetBrains for.peak. There's  a couple of others as well but these guys have a symbol server built in which means  you just open any assembly in there. If Visual Studio asks for symbols they decompile it  and give you source code that is whatever was compiled at the moment. It's not the actual  source code you get all the compiler optimizations and things like that but you do get a good  view of where in your code this thing is actually crashing. So let's do that. Let's configure  our symbol server. Let's enable that one. Disable just my code. Yes and then we should  be able to load the symbols. Ha, there we are. Sources from.peak decompiled from our  assembly for which we didn't have the code anymore. Where was this failing? In a task.run  where we would post download statistics to our download service. So whenever you download  a package we increment the number we save the header. Was this an install or a restore  or an update for example? And the version of the Nuget client so we know when we can  deprecate a specific version of the Nuget client for example. So this line was crashing.  Now this line if we went into our codes wasn't that special. The only thing it would do is  read some headers and post the number into some service somewhere. So yeah, not very  helpful. It is helpful. We knew where in our code this was crashing but not why this was  crashing. So an exception crashes IES. Well, yes, this was the actual code so the decompiler  actually did a pretty good job of bringing that code into Visual Studio. So this was  the actual code and our task.run post download statistics was actually failing. So what we  did was search Google Bing search whatever search engine we could find and we didn't  find anything useful about the exception that we were seeing in relation to HTTP requests  and async await and tasks and things like that. Until at a given point in time I think  after seven hours of searching that's all we did that day we found one guy who said  well unobserved exceptions in a task that run can crash your process. Who knew this?  I didn't know. So apparently whenever there's an exception happening in a piece of code  that you are running inside a task that you are no longer observing which is what we do  here. This is basically a fire and forget task that run. You know it will run eventually  to post the download statistics. If there's an exception in this post download statistics  code the task will crash but because no one is listening to the exception the process  will crash. Damn. So how do you solve this? Well apparently you can tell the task scheduler  that you want to attach an event handler to the unobserved task exception event and you  can just do your logging there and just exit the method with set observed and then the  exception is observed and is will no longer crash in this case. Reason for the crash by  the way was that our HTTP request would fail from time to time. So if we couldn't post  download statistics our frontend would go down because this task would throw. So we added  these few lines of code, added some logging and we were happy again and case closed. Awesome.  This was funny. That was a colleague of mine. Anyway. So the next thing we were seeing after  we fixed this one was high response times on our server. We were seeing really high response  times on people doing restores and installs on all the different packages. So what we  were seeing was very high CPU usage, long response times. Azure would auto scale. We  had auto scaling at the time adding more instances but basically what it would do was oh CPU is  high add more instances. Those new instances would get high CPU and we would add more instances  and basically spend our budget for the year. The profiler when we attached it also showed  lots of wait times in there as well. So that was definitely an issue but what was the cause  of that one? So we went to eating donuts again the parallel with profilers and so on. We  basically sat down, thought what could be the case of this and did some searching and  so on. And we found that there's a couple of possible causes for this issue. This one  was actually what we were seeing. When IAS launches your application it will assign a  couple of worker threads to the application to basically run things like HTTP requests  running in the back and so on or reading from the database for example. And by default I  think it's two threads that IAS starts per CPU or per logical CPU in your machine and  it's automatically adds new threads whenever they are required to serve traffic or serve  background tasks or whatever. The fun thing is that IAS and this is actually documented,  if IAS gets burst loads like a lot of requests in a short time, the thread number doesn't  scale up fast enough to cope with all that incoming traffic. So if you have a new machine  and you have one user and then two and then three and then four in a reasonable amount  of time, IAS will cope just fine. If all of a sudden your machine comes into the load  balancer and there's a thousand people hitting that machine, it will probably start waiting  for things to happen because it doesn't have enough background threads to do database and  HTTP work and so on. So we went in there and we changed this setting in the IAS settings  and this is what we saw. This was actually during NDC last year, I fixed this from the  speaker room. Seriously, so that was funny. We saw in App Insights when we rolled out  this change on all the different servers, the response times where they were really flaky  before would just stabilize in a nice smooth flat line and in this case that's actually  a good thing. Compared to the last week, you can see the graphs there as well from the  last week in App Insights. This was really much, much, much better than what we had at  the time. So case closed, I think. The only thing is we were running on cloud services  so we had to automatically change this setting whenever the machine would boot. Luckily,  you can add a startup script in there and do some tweaking when the machine starts up  and basically what you do is call into IAS's command line tool and set the right sections  in your applicationhost.config. That's what we did there. Case closed, but we were not  there yet. How much time do I have left? Still a bit. We were seeing, the next thing we were  seeing were package restore timeouts. So people doing restores were not getting high response  times. Their response times were normal except for a few requests that would just never come  back and timeout eventually. So what we were seeing on our V2-based Vits, which go through  Compute, which is in Visual Studio no longer the case, or in Visual Studio 2015, we actually  made an improvement with a new API that is served from static files on a CDN somewhere.  But with our previous versions, the V2 feeds would go through Compute and would show lots  of timeouts. These timeouts would not happen for a couple of hours. Then every seven to  15 hours, we would see this massive increase in response times, like extreme load times.  You can see one get by ID taking one minute. It's insane. But it would fix itself as well.  So after about 15 minutes, response times would drop again to a normal level. That's  an interesting one to find out what is going on there.  So there was no easy way to reproduce this. We tried reproducing the issue with the latest  code we had deployed and so on on local machines. We were unable to reproduce it on our local  machines or our dev environments, only happening on production.  So what we had to do was find a way to troubleshoot this issue. We normally don't do this, but  in this case, since it was only happening on production, we isolated one machine. We  let traffic through to it, but didn't let it respond traffic to our end users. So we  could see the traffic coming in and observe whatever was happening. What we did was we  already peed in and in Task Manager, we saw 100% CPU usage, which is awesome and which  was the issue we were seeing. But the problem with that is if you want to launch a profiler  when your machine is at 100% CPU, the profiler adds even more overhead. You start swapping  and doing process interchanges and so on. And yeah, you basically don't get a reliable  result from that. So damn.  So we sat down and started thinking and we thought, okay, what did we change last week  and the thing we changed was this minIoTread setting in IS. In app insights, we could learn  that the slow code path was find packages by ID. That was the only call that was being  slow and we thought, okay, what does this call do? This call actually does an HTTP request  to our search service to get back a result and to serve the package to your end user.  And that was a slow call path. So these things seemed to correlate somehow. We had enough  threads because we changed the setting, but our HTTP requests would probably cause this  issue because that code path does not do anything else than just making an HTTP request and  returning the response.  So we started searching and we found out that when you are using HTTP clients in a.NET  machine, that thing actually doesn't have a limit on the amount of requests it will  make. So if you write a console application, fire up 32,000 threads on your machine and  hit another machine with it, you will suffer TCP port exhaustion. All your ports are stuck  because all, yeah, there's no additional traffic flowing over the line because everything  is stuck at the OS level.  So we started thinking, okay, HTTP client is doing this nice, but that can be an issue  because you have a lot of TCP ports in a machine. So we read up on TCP IP a little bit more  and we found out that by default on Windows, whenever a connection is closed, the OS actually  holds on to the TCP port for about four minutes before it freezes because there may still be  traffic coming in, a load balancer may be acting up or whatever. Some packets may still  come in related to this connection and that's why Windows says, okay, I'm not freeing this  one for reuse yet because whenever something comes in, I want to basically ignore it and  not confuse whoever is reusing this TCP port. And after four minutes, it's free the port  and you can use it again.  Now, fun thing there is that for each fine packages by ID, which is our package restore  part, we would make an outgoing HTTP request, one port, but the user would also come in  and ask us for that restore. That's two ports. Lots of restores happening. Four minute wait  time in Windows. So basically what we were seeing was that we had TCP port exhaustion  and everything was waiting for Windows to free up those ports.  After reading up some more, we found out that you can actually block the HTTP client from  showing this behavior by setting your service point manager dot default connection limits  to a reasonable value. So if you change that, HTTP client will actually adhere to those  settings and if you set it to, for example, 500, it will only do 500 concurrent outgoing  requests from your machines. So that's what we did. We changed the codes and we did some  other optimizations there as well.  Well, of course, the default connection limit is one we did. We didn't want to have TCP  port exhaustion by just calling into our backend service. So we fixed that. But we also disabled  Nagling at the time. I'm not sure if you're familiar with what Nagling is. Basically, the  TCP IP protocol has an optimization where you have a certain package, packet size, which  can contain data if you make an outbound request or an incoming request. And if you have small  requests, TCP IP protocol will try to bundle those requests into as few packages, packets  as possible to not saturate your network connection and things like that and make things appear  more smoothly and more fast.  Thing was our traffic was really small because we just fetched PID from the search service.  So actually Nagling was working against us as well. So we disabled it and had smaller  packets flowing across the wire there. So both optimizations were enabled and our issue  was gone. Awesome. Some charts. The response time dropped from one minute to three seconds.  I think that was still during the flighting period where we just patched some servers.  And after that, response times dropped to a normal level at the time. So awesome. Case  closed again. How much time do I have left? 20 minutes. All right. There's more. Unfortunately.  What we were seeing. So we did all these optimizations and we followed this entire part of finding  a bug, quashing the bug and then hitting a new bug. So what we were seeing was 100%  memory usage on our medium Azure instances that we were running the service on. Okay.  Scale up. Bigger machines. Happy times. Everything fine until two or three minutes after deployment.  100% memory usage. You were like, hmm, okay. Nice. This was the moment where ASP.net said  they were going to do ASP.net next and we were seeing a lot of new users coming in and  so on. So we thought, okay, maybe we just have a lot of new users coming on. Maybe we need  just another bigger machine. So we did another upgrade. Two minutes in. 100% memory usage.  If at that point you don't realize there's an issue, then yeah, you can just keep on  spending and spending, but you will see the same thing on even bigger machines as well.  So what do you do? You start analyzing memory on the servers. What can you do to do this  on the server itself, which we don't like doing? So what we tried to do was reproduce  the issue on our local machines and that's what we did. So the way we did it is we basically  fetched a number of logs from our, where is my code? Where's my, there it is. Okay. So  we fetched a number of logs from our server, IS logs, which are typical standards logging  system and we downloaded a tool called JMeter. And JMeter is a Java-based tool which allows  you to do things like load testing and so on. Nice thing about JMeter is that on high  DPI screens, the UI is really, really small. But apart from that, it's actually a really  cool tool because you can do things like replaying traffic. Let's open my test plan. It is as  small for me as it is for you. Let's go in. Come on. Where did I put this document? There  it is. We basically configured a test plan which would read our access logs from IS.  So you basically tell this is my access log. You can read it from this specific path. Replay  it against this server and then you can give it things like the number of users that you  want to run against it, how you want to ramp up the number of users and so on. So to really  reproduce the traffic your servers were seeing at a given time. So what we did was we looked  into the logging. We decided on the window of the logs that we needed to replay this  issue on our local machines and our dev environments and that's what we did. So thank you, JMeter  for that. Your UI sucks but the tool is really, really awesome. So we did that and we went  into the memory. Now, who of you would say they are really familiar with.NET memory  management? Nobody? Good because I think nobody really is, not even the guys who wrote this  thing. But I'll give you a quick introduction on how.NET memory management works so that  you understand the problem we were seeing afterwards. So you replay the traffic but  before we look at the results there's a couple of things you have to know. So in.NET as opposed  to languages like C++ and so on, in.NET there's actually a run time, a managed run time that  allocates memory for you if you need memory. In C++ what do you do? You tell the OS I need  memory, they give you back an address in memory where you can store your stuff and if you  don't free it you will get an out of memory situation because nobody is freeing up the  memory for you. You have to really take care of that yourself. The way.NET works is whenever  your application starts the run time asks the OS can you please allocate a big block  of memory for me and I'll then in that block manage my own memory for you. So that's what .NET does and that big block of memory is the managed heap that you sometimes read about.  Whenever you will instantiate a new object in.NET it gets allocated in this managed  heap and that's really fast because you don't have to wait for the OS to give you access  to a certain address..NET can basically tell you okay here's memory because it already  has the memory available. Of course some unmanaged memory is also consumed like if you write  a UI based application, WinForms or XAML or whatever you also get things like graphics  buffers and things like that which are still unmanaged but most of the memory you are consuming  in your.NET applications is this big chunk of data to manage to heap. Now whenever your  variable goes out of scope and it's no longer needed you don't have to go and tell the OS  to basically free the memory up again..NET will manage this for you. It will notice that  the variable is out of scope. It will ignore that fact because it still has a big chunk  of memory available so it will not free the memory immediately. What it will do is at a  given point in time it will run the garbage collector. The garbage collector basically  what it does is it scans this entire block of memory searches for variables that are no  longer being used and then removes those from the managed block of memory so that the memory  can be reused in future times. Now I said it scans the entire block of memory and that's  quite an expensive operation to do. That's why.NET came up, well actually a lot of managed  languages came up with the concept of generations in this garbage collector. Basically when  you create a new variable or instantiate a new object or whatever the memory for that  is allocated in Gen0 as it's called. Gen0 is where short lift objects go. Like in a  method you create a string and two lines beyond that your method goes out of scope. Well that's  Gen0 and it can be reclaimed really really fast because.NET knows that probably all  the things in there or a lot of the things in there will probably be out of scope and  can be recycled anyway. Except for the objects that cannot be recycled. Those are moved into  Gen1. Gen1 is where medium lift objects live in.NET and.NET keeps them around until they  are no longer needed in there as well. So the garbage collector mostly runs on Gen0. Every  once in a while it runs on Gen1 to free the objects in there and if an object survives  Gen1 it's moved into Gen2. So the really long lift objects. If we think back to our download  counts example where we had this big dictionary of strings that were package IDs, inversions  and download counts. That thing would probably be either Gen2 or the large memory heap because  that's a long lift object. It lives the entire application lifetime and never gets to get  recycled by the garbage collector. So that's basically how.NET works. It has these generations  of memory and it frees the memory up for Gen0 mostly. Then every once in a while it does  Gen1 as well and then even fewer times it does Gen2. Reason for that is if you have a  long lift object there's no use in scanning this entire part of memory to free up memory  because it's probably still in use. So that's how it works. So visually you first have your  object in Gen0 then it moves to Gen1 if it's still alive. If not it's being reclaimed and  memory is freed. If in Gen1 your object lives on it will go to Gen2. If not it will go out  of Gen2. In Gen2 same thing if it keeps on being alive it will just remain in Gen2 until  future collections. If it can be freed it will be freed eventually. Then there's another  special case in this managed heap which is the large object heap. This is where large  objects go. If you have an object of more than 85 kilobytes in memory size it goes into  the large object heap because.NET thinks it's going to take a while to scan this entire  object and make sure that I can reclaim it during a garbage collection cycle. It basically  puts it there and that's where things don't have to end up ideally. But they go there.  One issue with the large object heap there is if you have a lot of objects in there there's  not a lot of optimization going on there by default which means that if you have a lot  of objects in there you get fragmentation and you will get eventually out of memory  exceptions. All right. Almost there. The.NET garbage collector is actually a really nice  thing because to your application it looks like you have an infinite amount of memory.  You just create new variables, create new objects, create whatever you want to create  in your memory..NET will handle the memory for you and make sure there's always some  memory available to do new things and your application doesn't have to care about what's  happening in there. Now when does this garbage collector run? That's actually not really  well documented. There's a couple of documents describing a lot of things but I don't think  everything is documented. Since.NET Core, the garbage collector is actually open source  so you can look in the sources but I think last time I checked it's a massive, I think  it's around 37,000 lines of code doing the memory management. So if you can go in there  and find out when the garbage collector runs please tell me. I would like to know. But  from observation most people say okay it happens when there's an out of memory condition. When  no memory is available in the managed heap, garbage collector will run and try to free  up some resources in memory. After a significant allocation, again our download counts if we  would allocate a new dictionary and populate this entire dictionary with 800,000 entries,  we were seeing garbage collection there. Even in our profiler we were seeing garbage collection  because of that. Also when it fails allocating resources it thinks okay maybe there's a memory  issue here, let's optimize this. When you have a profiler attached or when you force  it to do a garbage collection or when your application moves to the background. But the  most important thing from all these observations is that the garbage collector is not guaranteed  to run. If you have enough memory available for example it will run fewer times or maybe  not run at all. Interesting, keep that in mind. Let's analyze our memory usage. So we  replay traffic on our production instances and we got a memory snapshot. This is what  we got. The gray part is the unmanaged memory that's being used. The green part, sorry the  blue part is gen 0, the red part is gen 1 and the green part is gen 2. So what we can  see in this diagram is actually quite interesting because we can see gen 2 is growing continuously.  That's one thing. That's not ideal to be honest. What we can also see is that every time we  take a snapshot in memory, memory pressure drops and we get some memory back so some  garbage collection is happening which is a good thing. So let's dive into one of our  snapshots and see what was in memory at that time. Now I'm going to take snapshot 6 and  I'm going to take it for some reason. This is the reason. 2 million objects basically  have been removed from memory when I took this snapshot which means the garbage collector  did its work and what I will be able to see in this snapshot is probably what the garbage  collector didn't collect and that's what we were interested in. So let's open this  snapshot and wait until that memory shows us the things. It's actually a nice tool because  it shows you some of the most common memory issues that you can have like duplicate strings  or event handlers that you don't dispose of correctly and so on and you can dive into  whatever is in there. At the bottom we can see the heaps and as I already said on the  big chart we were seeing gen 2 was growing and growing and growing so let's see what's  in gen 2. We can go in there and see which objects are in there and by default it will  sort the objects by the number of retained bytes and that's basically the amount of bytes  this object holds on to in other objects and this object is an inject.activation.caching.cache.  Okay nice I cannot zoom there. I'll tell you there's one object of those which sort of  speaks for itself with a cache. You have one cache holding on to a number of objects. The  cache itself is only 48 bytes so nothing wrong there and it's keeping on or holding on to  90 megabytes of objects. Could be good, could be bad. So let's dive in. What's in this object?  We see that it has some entries and these entries are an array that contain keys and  values and items and it's basically easy to really get lost in this entire tree so that's  not really useful information. So let's take one step back and look at this entire list  one more time. Another object we see here is this guy. Of course there's a number of  collections and things like that in our memory as well but what's interesting is that our  entity framework context shows up as the sixth biggest object held in memory in this trace.  Hmm fishy. Especially since it's in gen 2 because I would expect if I serve requests  that have to make database calls we open an entity framework context, we handle the request,  we close the entity framework context and it gets garbage collected in gen 0 or the latest  in gen 1. Not in gen 2. What's even more interesting is that it's almost 80 megabytes of entity  framework contexts floating around in memory. Fishy. So let's go in there. We see that there's  a number of objects of this entity framework context. Let's group them by similar retention.  Basically look at who is keeping this entity framework context in memory. What's the reason  why this thing has not been garbage collected? Who is keeping this in memory? And the interesting  thing is that we see our NINJECT cache showing up as the object holding on to our entity framework  context. In fact it's holding on to 532 entity framework contexts in our gen 2 heap. Hmm. Alright.  So our DI container, NINJECT at the time, seemed to be the reason why we had a lot of  entity framework contexts still floating around in memory. So we decided, since NINJECT is  open source, to go through the codes and see if we could find what was happening and why  this was still being held in memory. And we found this garbage collection cache pruner.  It was kept in memory by the cache and we find this cache pruner. So let's look at the code in  there. It has, let me zoom in a little bit. Oh, that's fast. So fast. We live in the golden age  of CPU cycles and this is still so fast. Anyway, this garbage collection cache pruner would actually  make sure that our cache of objects that we instantiate through our DI container is every  once in a while being cleaned up and the object it holds on to are being garbage collected. The  way it does that is it has a weak reference and a weak reference is a type of object. If you  instantiate it and the garbage collector runs, it will basically remove the reference so you  know something has happened to it and someone has recycled this object so you know a garbage  collection happens. It has a list of caches. It has a timer and a thread pool timer. Now,  the interesting thing is whenever the timer runs, which is every, I think, 30 seconds it was by  default, it would purge prune cache if garbage collector has run. Okay, let's go there. Prune  cache if garbage collector has run. If you are on a PCL, you are unlucky. If not, we would lock.  We would check if our indicator, our weak reference has been collected or not. If it hasn't been  collected, we just return and don't clear our cache. Okay, remember that the garbage collector  is not guaranteed to run? That's the reason this variable was not collected and that's the reason  why this timer would eventually just return every single time and just keep all the objects that  it caches in its internal cache floating around and basically exhaust our memory continuously.  So, yeah, Ninject was not very friendly to us and we found some other people with exactly the  same issue and no fix yet. So, the thing we did was we changed to a different TI container,  autofack in this case. We ran the new analysis and we saw that response times dropped tremendously,  first of all. So, it was faster than Ninject as well and our memory issue was also gone and we  are now stable at a 4 gigabytes memory usage overall on our compute nodes there. So, that's  really, really nice improvement. Case closed. So, in conclusion, when you start debugging and  when you start spelunking an entire chain of possible bugs that follow one after another,  you will have to build some familiarity with your system that you are trying to debug and  trying to investigate. Try to, in your mind, think like the compiler, think like.NET's garbage  collector, think like whatever can happen in your own codes and that will really help you  finding these issues. Bugs hides and we found out that whenever we fixed a bug, there would be a  new bug popping up because we fixed the original bug and we would just open the floodgates to  the new one. So, keep that in mind if you fix this type of issues, you may run into the next one  the next day or even the next hour. What I did learn from this experience, I've been doing this  for three, four months, this entire thing, what I did learn is that I learned a lot about how .NET works and I learned that I actually like spelunking through memory traces, through performance,  snapshot sense and so on because you learn how your code is behaving even better, you learn how  the.NET framework is behaving in the different versions of the.NET framework and you overall  build experience for the next bug that comes along. So, if you have an issue like this, don't go,  it's an ops problem, dive in and try and investigate, it's really, really useful to do. With that,  thank you for being here and enjoy the rest of NDC.
Sherlock_Homepage_A_detective_story_about_runnin_0_59.png Sherlock_Homepage_A_detective_story_about_runnin_60_743.png Sherlock_Homepage_A_detective_story_about_runnin_744_1079.png Sherlock_Homepage_A_detective_story_about_runnin_1080_3395.png Sherlock_Homepage_A_detective_story_about_runnin_3396_6071.png Sherlock_Homepage_A_detective_story_about_runnin_6072_7955.png Sherlock_Homepage_A_detective_story_about_runnin_7956_10199.png Sherlock_Homepage_A_detective_story_about_runnin_10200_10355.png Sherlock_Homepage_A_detective_story_about_runnin_10356_11051.png Sherlock_Homepage_A_detective_story_about_runnin_11052_16271.png Sherlock_Homepage_A_detective_story_about_runnin_16272_16655.png Sherlock_Homepage_A_detective_story_about_runnin_16656_17231.png Sherlock_Homepage_A_detective_story_about_runnin_17232_20567.png Sherlock_Homepage_A_detective_story_about_runnin_20568_20651.png Sherlock_Homepage_A_detective_story_about_runnin_20652_20951.png Sherlock_Homepage_A_detective_story_about_runnin_20952_21287.png Sherlock_Homepage_A_detective_story_about_runnin_21288_21671.png Sherlock_Homepage_A_detective_story_about_runnin_21672_21743.png Sherlock_Homepage_A_detective_story_about_runnin_21744_21803.png Sherlock_Homepage_A_detective_story_about_runnin_21804_21851.png Sherlock_Homepage_A_detective_story_about_runnin_21852_21899.png Sherlock_Homepage_A_detective_story_about_runnin_21900_22787.png Sherlock_Homepage_A_detective_story_about_runnin_22788_22847.png Sherlock_Homepage_A_detective_story_about_runnin_22848_22895.png Sherlock_Homepage_A_detective_story_about_runnin_22896_23027.png Sherlock_Homepage_A_detective_story_about_runnin_23028_23807.png Sherlock_Homepage_A_detective_story_about_runnin_23808_23975.png Sherlock_Homepage_A_detective_story_about_runnin_23976_24119.png Sherlock_Homepage_A_detective_story_about_runnin_24120_24167.png Sherlock_Homepage_A_detective_story_about_runnin_24168_24275.png Sherlock_Homepage_A_detective_story_about_runnin_24276_25127.png Sherlock_Homepage_A_detective_story_about_runnin_25128_25463.png Sherlock_Homepage_A_detective_story_about_runnin_25464_26075.png Sherlock_Homepage_A_detective_story_about_runnin_26076_26555.png Sherlock_Homepage_A_detective_story_about_runnin_26556_28139.png Sherlock_Homepage_A_detective_story_about_runnin_28140_28235.png Sherlock_Homepage_A_detective_story_about_runnin_28236_30071.png Sherlock_Homepage_A_detective_story_about_runnin_30072_30695.png Sherlock_Homepage_A_detective_story_about_runnin_30696_31067.png Sherlock_Homepage_A_detective_story_about_runnin_31068_31139.png Sherlock_Homepage_A_detective_story_about_runnin_31140_31355.png Sherlock_Homepage_A_detective_story_about_runnin_31356_31991.png Sherlock_Homepage_A_detective_story_about_runnin_31992_32243.png Sherlock_Homepage_A_detective_story_about_runnin_32244_32915.png Sherlock_Homepage_A_detective_story_about_runnin_32916_33719.png Sherlock_Homepage_A_detective_story_about_runnin_33720_36071.png Sherlock_Homepage_A_detective_story_about_runnin_36072_36407.png Sherlock_Homepage_A_detective_story_about_runnin_36408_36455.png Sherlock_Homepage_A_detective_story_about_runnin_36456_42215.png Sherlock_Homepage_A_detective_story_about_runnin_42216_44183.png Sherlock_Homepage_A_detective_story_about_runnin_44184_45107.png Sherlock_Homepage_A_detective_story_about_runnin_45108_45311.png Sherlock_Homepage_A_detective_story_about_runnin_45312_45611.png Sherlock_Homepage_A_detective_story_about_runnin_45612_46439.png Sherlock_Homepage_A_detective_story_about_runnin_46440_46703.png Sherlock_Homepage_A_detective_story_about_runnin_46704_49487.png Sherlock_Homepage_A_detective_story_about_runnin_49488_50099.png Sherlock_Homepage_A_detective_story_about_runnin_50100_50579.png Sherlock_Homepage_A_detective_story_about_runnin_50580_57743.png Sherlock_Homepage_A_detective_story_about_runnin_57744_59363.png Sherlock_Homepage_A_detective_story_about_runnin_59364_59963.png Sherlock_Homepage_A_detective_story_about_runnin_59964_60083.png Sherlock_Homepage_A_detective_story_about_runnin_60084_62027.png Sherlock_Homepage_A_detective_story_about_runnin_62028_62075.png Sherlock_Homepage_A_detective_story_about_runnin_62076_64595.png Sherlock_Homepage_A_detective_story_about_runnin_64596_64643.png Sherlock_Homepage_A_detective_story_about_runnin_64644_76259.png Sherlock_Homepage_A_detective_story_about_runnin_76260_77351.png Sherlock_Homepage_A_detective_story_about_runnin_77352_77867.png Sherlock_Homepage_A_detective_story_about_runnin_77868_81959.png Sherlock_Homepage_A_detective_story_about_runnin_81960_82139.png Sherlock_Homepage_A_detective_story_about_runnin_82140_85847.png Sherlock_Homepage_A_detective_story_about_runnin_85848_86123.png Sherlock_Homepage_A_detective_story_about_runnin_86124_86723.png Sherlock_Homepage_A_detective_story_about_runnin_86724_86783.png Sherlock_Homepage_A_detective_story_about_runnin_86784_88871.png Sherlock_Homepage_A_detective_story_about_runnin_88872_89087.png Sherlock_Homepage_A_detective_story_about_runnin_89088_89115.png
All right. Good morning, everyone. Can everyone hear me? Awesome. Thank you. I was a little bit worried when I saw no one sitting in the middle, but it sort of explains itself because the screens are over there. So thank you. It's not because I smell, which is awesome after a couple of days of NDC. Welcome to this session, Sherlock Homepage. It's a big detective story about running large-scale services, and we'll see in a bit what that means, but first let's dive in. So on one good day last year, I think it was around April last year, we had an issue with our life sites. We were completely unavailable. Nothing was available. None of our customers could use our website. So what we were seeing was that our primary website location was just gone off the Internet. Nothing available. If we used our domain name, we could not hit our website, and nothing was visible there. So that was an issue. Now, the good thing is we are smart people, and of course we have a secondary location, and we have traffic manager in front, which is a DNS service that does failover in case the primary location goes down. So awesome. We thought we had fixed it. Problem was, when that failover happens, we found out that the secondary location was also unavailable. And you would think we would be as smart to have a third location, but unfortunately no. So we were completely gone off the Internet. So that's a big issue. Website down, our customers were complaining, Twitter was on fire, everyone was complaining that we had an issue. So we went on an initial investigation, so we got some monitoring alerts and stuff like that, and we started looking into what was happening there. And of course we saw that the website was unavailable from the Internet, but we did see that all the server instances in both the primary and secondary location were all available. If we hit the direct end points of each individual machine, we could reach the individual machine and just look at the website and do whatever we wanted there. The only thing was that traffic manager, so the DNS didn't work, we couldn't reach the websites. And if we would hit the load balancer end points that was in front of those web servers, we would also not hit the website. So either we had a DNS issue or the load balancer would have an issue. So we went to look and we found running on Azure that it actually was the load balancer causing a problem. So I don't know if you noticed, but if you run cloud services on Azure, you can actually instruct the load balancer to check your websites every couple of minutes to see if it's still available. By default, it just checks the root of your web URL, sees if a 200 OK comes back, and if that's OK, your machines are in the load balancer pool and they will get traffic. Now in our case, we had customized this and we had a custom internal API endpoint where we went to API slash status. And if that one didn't give back a 200 OK, then that machine would go out of the load balancer rotation and would become unavailable through the load balancer. Now the funny thing there was that eventually all the machines were going out of the load balancer because this endpoint was returning a non-successful status code, which meant the load balancer was there. The web servers were there, throwing 500 errors, but the load balancer would just take them out of rotation. And that happened on both locations, so primary location and secondary location, which meant we were just completely gone because all traffic would stop at the load balancer because the load balancer had nothing to serve traffic to. We found out in our codes of this status service, we found out that the root cause of this issue could be one of many services. This status endpoint internally checks if our REST APIs are available, if our SQL database is available, if our storage is available, if our search API is available, and if we could post statistics. So one of these services was probably down and because of that, this status endpoint was returning an error, which in turn would remove all the instances from the load balancer and just make us disappear from the face of the earth. So we solved it and we basically removed the load balancer probe so that all the machines would be back in business. And we started digging in. Now before we dig in, I do want to mention this one. I actually like the website highscalability.com very, very much because they have interesting topics on all the big companies like Twitter, like LinkedIn, on their architectures and stuff like that. And every now and then they have an insightful post and I especially like this one where they mentioned the book called Mindhunter, which is written by an FBI profiler who does investigations on serial killers and psychopaths and so on. And it's funny that hunting bugs in your codes and hunting issues in your code and your applications is quite similar to how those guys work. They try to bring their minds into how the system works into the bug or the psychopath in this case would be doing and why he would do that and what the approach would be to cause havoc and things like that. But the bottom line of this book is you have to know what it's like to be in the shoes of the psychopath or serial killer or in this case the bug or the issue in your system. Another nice quote in there is that you have to have a sympathy for the machine. You have to really think like the machine, think like your code, know your code, know whatever is happening and so on in your system. So that's a really important thing. And maybe you don't know your entire system completely. Imagine you're new on the job and you're tasked to investigate an issue like this, but you'll probably have done something similar in a previous job. So you take away all that experience to your next job and you get to know this type of distributed systems and how typically these architectures are built. So we had that knowledge. We had empathy for our system because yeah, our system was down and we were thinking like what could be the case that our system is down. And all that combined, we basically had a hunch thinking maybe it's the load balancer and because of that experience, we proved that it actually was the load balancer taking all the machines out of rotation. One nice quote in this book as well, which I don't have on the slides, is that bugs are like serial killers. If you put them in society and they are in the right circumstances, nothing will happen. They will just remain quiet and do nothing until at a given point the right circumstances are there and then they take action and they can take one action and then they can take the next one and maybe the next one until they get caught. And the same with bugs and that's the thing we are going to see in this story. We fix a bug and a new bug turns up and we basically kept on rolling there. So thank you. Welcome to Sherlock Homepage, a detective story about running large scale web services. I'm Martin Bajo. I work at Microsoft on the NuGet team. So you can imagine what this large web service could have been. You can also imagine last year, who would have shot me on the stage last year if I told them I was from the NuGet team? I would have shot myself. All right. Thank you. So you may have noticed in the past year that things have improved on the server side and that we did a lot of work and that's what this talk is going to be about. And there's a couple of nice things in there. But before we dive in there, I want to give you some history on how NuGet came about and how the services were built and what our architecture looked like last year around, yeah, I think March, April timeframe. So our site serves in case you don't know NuGet. We serve packages to all.NET developers in the world and with.NET core coming about, I think we are only going to see more traffic on NuGet than what we currently already have. On average, we are good for some 10 million requests per day on our compute nodes. We also have a lot of stuff in a static CDN type of approach where we don't have to have compute to serve requests, which is awesome because we can offload a lot of things from our dynamic servers, but still we have 10 million requests per day on that dynamic website. It was built four or five years ago. I still feel that it was built as a proof of concept, saying, okay, we have OData, which is awesome. We want to do this packaging thing, which everyone is doing. So let's maybe create a database, put a packages table in there, have storage where we can serve the packages, then slam OData on top, basically expose the SQL data over HTTP, and yeah, NuGet. So that was how it was built. Unfortunately, after a while, the team found out that those things were not the good approach. So there were some optimizations like the OData feed would not always go to the database. You would hijack some commonly used queries like package restores, for example, and move them to a different API internally. That said, last year we had some rough times at this time. I still know running around here at NDC, talking to some of the other speakers. I know Paul Stack was continuously bugging me like, hey, Martin, it's NuGet up. And I was like, yes, it is up right now, but maybe in an hour or not. So we had some rough times. So our architecture at the time was we had front-end servers in two regions, so two data center locations in Azure. And the front-end servers run MVC and OData. MVC for the website, if you go to NuGet.org and you register and you search for packages and stuff like that, that's the MVC site. We also had the WCFO data to serve the packages to all the clients like Visual Studio, NuGet.exe, and so on. That said, we have, of course, a SQL database in the back-ends to serve package metadata, download counts, and things like that, and those two communicate with one another. So this was the initial architecture that we had, which didn't really scale because everyone would hit the database continuously because the OData layer was a really thin layer on top of that SQL database. So we did some improvements. And the biggest improvement there was that we started using Lucene for search because we have a lot of searches. Like in Visual Studio, if you search for a package, that would be a search, and it would search pretty much the entire database if you would hit SQL. So we basically hijacked that type of request and put it on a search service that runs Lucene. Also, for package restores, if you search a package by ID inversion, which is like an ID lookup, we go to that search service which has a cache of this package, has that metadata, and lives at this URL so we can quickly serve your data. Now, of course, this thing has to have data as well. And we store our index and download counts, documents, and things like that on Azure Storage. But of course, we need that storage to be populated with data from the SQL database. So we have some job VM runners that basically do things like creating the index every couple of minutes, updating statistics if you download a package that you can see an increment in a download count or things like the download counts from the last six weeks and so on. That was the architecture. Now, did we solve the crime of this load balancer going RE? I don't think so. We solved the immediate danger where we were offline. We basically told the load balancer to not care about the status endpoint and still have the website up and running. But did we solve the crime? No. We still don't know what costs this load balancer probe to go RE. So one of our services cost this. SQL, storage, our search service, or our metric service. We have a check on the gallery service there as well. But because that is hosted on the same system, we are pretty confident that that was not the issue because it would, yeah, sort of, it's a redundant check. So one of these four services was actually acting up and we had to find out what was the cost of this issue. So what we did was locks-pulunking. You dive into the locks, you try and search clues on what went wrong and why the service was actually acting up. So the first thing we did was check some SQL database locks and we logged into the Azure portal and we wanted to see the locks and we found out we had none. That's been fixed, of course, but that was quite inconvenient at the time because we didn't have those locks. So we couldn't check the database if that one had been down at that moment in time or not. So we sort of knew the database may be yes, maybe no, that was the cost of the issue, but we couldn't say for sure because we had no locks of that one at the time. We looked into storage locks. On Azure, you can basically enable logging on storage and you can see which requests pass through what your error rate is and things like that and storage was healthy as a fish in the water. Nothing was wrong with storage. So definitely not storage, maybe SQL. We looked at search. We have some extensive logging on there as well, but we didn't see anything out of the ordinary there either. All 200 OKs coming back from search and nothing wrong there. We looked into our metric service. Also nothing wrong there. It's basically something that has been deployed, has been stable for months in a row, actually two years in a row where we didn't make any changes to the process and it just kept on working perfectly fine. So yeah, we still weren't the wiser and we started to look around at the crime scene. We started to put those little yellow markers of evidence on the VMs. So we logged into our Azure VMs and we started looking at IAS logs, event viewer logs and things like that. We did some profiling as well and yeah, I still have those traces with me. Well, most of the traces. I didn't keep them all, which is unfortunate, but I do have a couple. So one of the things we found on our gallery database was this trace, sorry on our gallery VMs. We did a trace and we got back this data. So there's a couple of things to note here. First of all, the CPU diagram looks quite healthy. It's not out of the ordinary. No excessive garbage collections happening or something like that. So actually the service looked quite well when this issue was happening. Another thing we saw was lock contention. No locks, no waiting for locks and things like that. There is quite some time spent waiting, but we found out that wait time was basically just because the service didn't get enough traffic and the CPU was idling because yeah, there's almost no traffic. What we did find out though was that the top called methods and I would like to zoom into the right. Okay, you'll have to believe me on my words or try to zoom in yourself. The top method we had was this hijack method. So that was the method called most in our search in our gallery server, which is the method that actually takes the OData query coming in, translates it to the REST API of our search service and then makes the call to the search service and fetches that data and returns it to the client. So that was the most called methods at that time. So we were like, hmm, so maybe it is search even though we didn't find anything on search. So we went on and we went into profiling the search service. I have those traces as well. And this looks a bit more problematic. You see CPU is quite okay, but garbage collection is crazy. This machine was doing 65% of work was it was doing garbage collection, which is insane. Another thing we found on search was lock contention. 16% of the time spent in our search service, it was waiting for locks to be freed. So we had lock statements in our codes and the code was just waiting for those to be freed again and to continue the work. Damn, that's too bad things. So lots of garbage collection and locks. Now, fun thing is if we filter on where are you waiting for locks, that is the moments where it's not garbage collecting. So we really had an issue there at the moment. So we went and we looked for what could be the cost of this lock statement and we found that our Lucene reloads method was actually waiting for a lock to be freed. That's not bad because the way Lucene works is it loads an index into memory so you can search through it. But before it has been loaded completely, you cannot search in that index because things would break down and crash. So Lucene has a lock statement in there. We had a lock statement around that code to wait until the index was loaded before serving traffic on that index. The one issue we had there, though, was the following. Of course, it was search. This looked really bad and we started looking into the code and we found in our searcher manager, by the way, we are open source. So if you look into those commits, you can actually see these things. We had a start reopen method in there. And that method would basically lock until the entire index was loaded into memory and we could do search on that. Now, this is not very problematic because it's how you want to work with Lucene. The moment where it starts to become problematic is when this is in your HTTP request path because that means all your users are waiting at that moment. And that was what was happening. We were basically blocking HTTP requests because the index wasn't loaded yet or refreshed completely yet and we had a lock statement in there. So we removed that one, refactored a little bit and found that it worked perfectly fine. Another thing we found in this profiling session was this excessive garbage collection. So I don't have the traces anymore, but we also did a memory profiling session there and we found out that this garbage collection was caused by excessive allocation of strings and J objects and dictionaries. Turns out when we serve traffic on our search service, we try to correlate the search query with the download count of the packages. So that packages with higher download counts in the past few weeks rank a little bit higher than packages with lower download counts. Now, to load those download counts because they continuously update, we don't want to write them into the index because the way it works is you write the document in the index and if you want to update the document, you actually have to delete and re-add the document. That causes a lot of churn and a lot of waiting, merging, things like that. So we don't want to do that. What we do is we have a blob in storage containing all these download counts. We load it as a JSON blob and we use that as a source of this data. Turns out that we had some nice code in there. Remember, we have around, I think, around eight or 900,000 packages right now and every couple of minutes, we would do this, load download counts into a dictionary of package ID, package version and the download count. Anyone see what's wrong with this code? There's nothing wrong with this code. There is something wrong with this code if you are loading 800,000 entries into these dictionaries and you reallocate the entire dictionary every five minutes. That's the problem here. Because we were doing that, the garbage collector would have to garbage collect every single entry in these dictionaries, recreate the dictionary and this was happening every five minutes. So every five minutes, this would happen. Garbage collection would take some time. Then we would hit our lock so we would wait some more time and then after five minutes, we would start this cycle again and again and again and this was why search was misbehaving. So what we did was we basically replaced this with a dictionary and we just update the values. If the package is already in the dictionary, we just update the download counts in the dictionary instead of recreating the entire dictionary with all its entries, reducing memory traffic and reducing garbage collection a lot. So that was what we did there. Case closed, awesome. We found out why we were down and what the issue was and happy times. Now remember when I said that bugs are like serial killers in society when given the right circumstances, they do something until you catch them. Well, we caught this bug but the circumstances changed by fixing this bug so it had a new opportunity. Before we dive into that, we did some things. So we found out we had no SQL logging at the time so we enabled those things. This was also the time when app insights came about on Azure and we started looking into that one. Not sure if you noticed this thing but I'm just going to quickly show you so you have an idea. App insights basically correlates your server response times, all your different performance counters and so on with HTTP requests so we can see which request is slowest. We can correlate it with the time, we can correlate it with which dependencies have been called like storage or SQL and so on. So it's basically a search engine for monitoring data and you can see whatever is happening there. If there's an exception, you can see the stack trace, things like that. So really useful tool to do some quick debugging. It's like a continuous mini profiler running in Azure and collecting all that data. So quite nice. So we did that. We added some more logging. App insights was introduced in all the different services and we thought happy times we can continue with our regular work. Now unfortunately, one of those days we had internal server errors on all our machines during package restores. So the thing is when you open up a new project and you build the project for the first time and Nuget packages haven't been downloaded yet, what Visual Studio does is restore those packages from our services but of course if we say internal server error at that time, people get no packages and people get mad and want to kill us. So that's what we were seeing. What we were seeing in App Insights this time was that of course a lot of internal server errors were happening. We saw that the response times went up while the number of requests actually went down. If we looked in event viewer and in the different views in App Insights, we saw that IIS was crashing on us on the machines themselves. Well actually on the log location we found a lot of crash dumps from IIS as well. So something was fishy here. IIS was crashing every couple of minutes. That's not good. So IIS crashes. What do you do to investigate? Well there's event viewer which tells you some things but in case you don't know, IIS is basically a fancy wrapper with additional things around HTTP.sys which is a kernel module in Windows that actually serves HTTP traffic. So IIS is just a fancy thing around HTTP.sys. Now IIS does logging but this HTTP.sys kernel module also does logging. So if on Azure you go into this spot in system 32 and actually on any IIS web server you can go there, you will find different logs that give you different information about connection states and so on. And what we saw in that log was a lot of entries saying connection abandoned by request queue. That's a nice error and if you search for it on Google, not on Bing because Bing sucks in Belgium where I live. It's actually quite nice in the US whenever I'm there. But we search for it and you cannot find any results on any of the popular search engines. You can find some information, some vague information on MSDN but somewhere we found that this error message means that a worker process from the application pool has quit unexpectedly or orphaned a pending request by closing its handle. So this basically means IIS gave up, we close the connection and see you next time. That's basically what the error was. So we knew something was happening, IIS was crashing, HTTP.sys was giving up on users. So we went to the gift of the gods which is crash dumps and we pulled those from the machines and we looked into that. Now if there are any hardcore debuggers in here you will probably look at me and say why aren't you not using WinDBG because WinDBG is quite complex and not the best demo. So that's why. But fortunately you can also open crash dumps in plain old Visual Studio and it's actually quite good. You get some information about the crash dump and you can see that the threat tried to read or write to a virtual address for which it doesn't have appropriate access, an exception. So this exception was the last thing recorded in this entire dump before IIS gave up. So this is probably the cause of IIS crashing. Now this error, if you search for it, you don't find a lot of useful information. You find lots of useful information like this can be why it crashes but still you get 100,000 results with every result actually being a different result telling something else about the cause of this error. So what you can do is there's actually a couple of nice windows as well in Visual Studio where you can look into the threats and states at that time in the application. But the fun thing is you can also debug a crash dump. So let's do that. Let's debug with managed only and you actually get the states of the machine at the moment this crash dump was taken and you can look into variables if you have a full dump. This is a mini dump so you only get stack traces. So we see this exception and it's the same exception we already saw if there's a hand, sorry, access violation, reading location, some number. Okay, let's break like you would do in a regular debugging session and you see there's no symbols. I'll cover that in a bit but we can also go hardcore and just view the disassembly and as you can see this move statement failed and that's why IS crashed. Any questions? No. So yeah, that's not very helpful this statement. You could go through the IL and there's actually a couple of guys within Microsoft who would go through the IL and just debug it from there but they are insane. We took the other approach which was finding the symbols for this code. Now we found out that our build server would not publish symbols anywhere and we found out that our retention policy on the build server had already deleted the symbols for this specific deployment of our service which meant we had no symbols and we could not correlate with whatever was happening at the time. Good thing there are some awesome tools available where you can just decompile whatever is happening. So thank you JetBrains for.peak. There's a couple of others as well but these guys have a symbol server built in which means you just open any assembly in there. If Visual Studio asks for symbols they decompile it and give you source code that is whatever was compiled at the moment. It's not the actual source code you get all the compiler optimizations and things like that but you do get a good view of where in your code this thing is actually crashing. So let's do that. Let's configure our symbol server. Let's enable that one. Disable just my code. Yes and then we should be able to load the symbols. Ha, there we are. Sources from.peak decompiled from our assembly for which we didn't have the code anymore. Where was this failing? In a task.run where we would post download statistics to our download service. So whenever you download a package we increment the number we save the header. Was this an install or a restore or an update for example? And the version of the Nuget client so we know when we can deprecate a specific version of the Nuget client for example. So this line was crashing. Now this line if we went into our codes wasn't that special. The only thing it would do is read some headers and post the number into some service somewhere. So yeah, not very helpful. It is helpful. We knew where in our code this was crashing but not why this was crashing. So an exception crashes IES. Well, yes, this was the actual code so the decompiler actually did a pretty good job of bringing that code into Visual Studio. So this was the actual code and our task.run post download statistics was actually failing. So what we did was search Google Bing search whatever search engine we could find and we didn't find anything useful about the exception that we were seeing in relation to HTTP requests and async await and tasks and things like that. Until at a given point in time I think after seven hours of searching that's all we did that day we found one guy who said well unobserved exceptions in a task that run can crash your process. Who knew this? I didn't know. So apparently whenever there's an exception happening in a piece of code that you are running inside a task that you are no longer observing which is what we do here. This is basically a fire and forget task that run. You know it will run eventually to post the download statistics. If there's an exception in this post download statistics code the task will crash but because no one is listening to the exception the process will crash. Damn. So how do you solve this? Well apparently you can tell the task scheduler that you want to attach an event handler to the unobserved task exception event and you can just do your logging there and just exit the method with set observed and then the exception is observed and is will no longer crash in this case. Reason for the crash by the way was that our HTTP request would fail from time to time. So if we couldn't post download statistics our frontend would go down because this task would throw. So we added these few lines of code, added some logging and we were happy again and case closed. Awesome. This was funny. That was a colleague of mine. Anyway. So the next thing we were seeing after we fixed this one was high response times on our server. We were seeing really high response times on people doing restores and installs on all the different packages. So what we were seeing was very high CPU usage, long response times. Azure would auto scale. We had auto scaling at the time adding more instances but basically what it would do was oh CPU is high add more instances. Those new instances would get high CPU and we would add more instances and basically spend our budget for the year. The profiler when we attached it also showed lots of wait times in there as well. So that was definitely an issue but what was the cause of that one? So we went to eating donuts again the parallel with profilers and so on. We basically sat down, thought what could be the case of this and did some searching and so on. And we found that there's a couple of possible causes for this issue. This one was actually what we were seeing. When IAS launches your application it will assign a couple of worker threads to the application to basically run things like HTTP requests running in the back and so on or reading from the database for example. And by default I think it's two threads that IAS starts per CPU or per logical CPU in your machine and it's automatically adds new threads whenever they are required to serve traffic or serve background tasks or whatever. The fun thing is that IAS and this is actually documented, if IAS gets burst loads like a lot of requests in a short time, the thread number doesn't scale up fast enough to cope with all that incoming traffic. So if you have a new machine and you have one user and then two and then three and then four in a reasonable amount of time, IAS will cope just fine. If all of a sudden your machine comes into the load balancer and there's a thousand people hitting that machine, it will probably start waiting for things to happen because it doesn't have enough background threads to do database and HTTP work and so on. So we went in there and we changed this setting in the IAS settings and this is what we saw. This was actually during NDC last year, I fixed this from the speaker room. Seriously, so that was funny. We saw in App Insights when we rolled out this change on all the different servers, the response times where they were really flaky before would just stabilize in a nice smooth flat line and in this case that's actually a good thing. Compared to the last week, you can see the graphs there as well from the last week in App Insights. This was really much, much, much better than what we had at the time. So case closed, I think. The only thing is we were running on cloud services so we had to automatically change this setting whenever the machine would boot. Luckily, you can add a startup script in there and do some tweaking when the machine starts up and basically what you do is call into IAS's command line tool and set the right sections in your applicationhost.config. That's what we did there. Case closed, but we were not there yet. How much time do I have left? Still a bit. We were seeing, the next thing we were seeing were package restore timeouts. So people doing restores were not getting high response times. Their response times were normal except for a few requests that would just never come back and timeout eventually. So what we were seeing on our V2-based Vits, which go through Compute, which is in Visual Studio no longer the case, or in Visual Studio 2015, we actually made an improvement with a new API that is served from static files on a CDN somewhere. But with our previous versions, the V2 feeds would go through Compute and would show lots of timeouts. These timeouts would not happen for a couple of hours. Then every seven to 15 hours, we would see this massive increase in response times, like extreme load times. You can see one get by ID taking one minute. It's insane. But it would fix itself as well. So after about 15 minutes, response times would drop again to a normal level. That's an interesting one to find out what is going on there. So there was no easy way to reproduce this. We tried reproducing the issue with the latest code we had deployed and so on on local machines. We were unable to reproduce it on our local machines or our dev environments, only happening on production. So what we had to do was find a way to troubleshoot this issue. We normally don't do this, but in this case, since it was only happening on production, we isolated one machine. We let traffic through to it, but didn't let it respond traffic to our end users. So we could see the traffic coming in and observe whatever was happening. What we did was we already peed in and in Task Manager, we saw 100% CPU usage, which is awesome and which was the issue we were seeing. But the problem with that is if you want to launch a profiler when your machine is at 100% CPU, the profiler adds even more overhead. You start swapping and doing process interchanges and so on. And yeah, you basically don't get a reliable result from that. So damn. So we sat down and started thinking and we thought, okay, what did we change last week and the thing we changed was this minIoTread setting in IS. In app insights, we could learn that the slow code path was find packages by ID. That was the only call that was being slow and we thought, okay, what does this call do? This call actually does an HTTP request to our search service to get back a result and to serve the package to your end user. And that was a slow call path. So these things seemed to correlate somehow. We had enough threads because we changed the setting, but our HTTP requests would probably cause this issue because that code path does not do anything else than just making an HTTP request and returning the response. So we started searching and we found out that when you are using HTTP clients in a.NET machine, that thing actually doesn't have a limit on the amount of requests it will make. So if you write a console application, fire up 32,000 threads on your machine and hit another machine with it, you will suffer TCP port exhaustion. All your ports are stuck because all, yeah, there's no additional traffic flowing over the line because everything is stuck at the OS level. So we started thinking, okay, HTTP client is doing this nice, but that can be an issue because you have a lot of TCP ports in a machine. So we read up on TCP IP a little bit more and we found out that by default on Windows, whenever a connection is closed, the OS actually holds on to the TCP port for about four minutes before it freezes because there may still be traffic coming in, a load balancer may be acting up or whatever. Some packets may still come in related to this connection and that's why Windows says, okay, I'm not freeing this one for reuse yet because whenever something comes in, I want to basically ignore it and not confuse whoever is reusing this TCP port. And after four minutes, it's free the port and you can use it again. Now, fun thing there is that for each fine packages by ID, which is our package restore part, we would make an outgoing HTTP request, one port, but the user would also come in and ask us for that restore. That's two ports. Lots of restores happening. Four minute wait time in Windows. So basically what we were seeing was that we had TCP port exhaustion and everything was waiting for Windows to free up those ports. After reading up some more, we found out that you can actually block the HTTP client from showing this behavior by setting your service point manager dot default connection limits to a reasonable value. So if you change that, HTTP client will actually adhere to those settings and if you set it to, for example, 500, it will only do 500 concurrent outgoing requests from your machines. So that's what we did. We changed the codes and we did some other optimizations there as well. Well, of course, the default connection limit is one we did. We didn't want to have TCP port exhaustion by just calling into our backend service. So we fixed that. But we also disabled Nagling at the time. I'm not sure if you're familiar with what Nagling is. Basically, the TCP IP protocol has an optimization where you have a certain package, packet size, which can contain data if you make an outbound request or an incoming request. And if you have small requests, TCP IP protocol will try to bundle those requests into as few packages, packets as possible to not saturate your network connection and things like that and make things appear more smoothly and more fast. Thing was our traffic was really small because we just fetched PID from the search service. So actually Nagling was working against us as well. So we disabled it and had smaller packets flowing across the wire there. So both optimizations were enabled and our issue was gone. Awesome. Some charts. The response time dropped from one minute to three seconds. I think that was still during the flighting period where we just patched some servers. And after that, response times dropped to a normal level at the time. So awesome. Case closed again. How much time do I have left? 20 minutes. All right. There's more. Unfortunately. What we were seeing. So we did all these optimizations and we followed this entire part of finding a bug, quashing the bug and then hitting a new bug. So what we were seeing was 100% memory usage on our medium Azure instances that we were running the service on. Okay. Scale up. Bigger machines. Happy times. Everything fine until two or three minutes after deployment. 100% memory usage. You were like, hmm, okay. Nice. This was the moment where ASP.net said they were going to do ASP.net next and we were seeing a lot of new users coming in and so on. So we thought, okay, maybe we just have a lot of new users coming on. Maybe we need just another bigger machine. So we did another upgrade. Two minutes in. 100% memory usage. If at that point you don't realize there's an issue, then yeah, you can just keep on spending and spending, but you will see the same thing on even bigger machines as well. So what do you do? You start analyzing memory on the servers. What can you do to do this on the server itself, which we don't like doing? So what we tried to do was reproduce the issue on our local machines and that's what we did. So the way we did it is we basically fetched a number of logs from our, where is my code? Where's my, there it is. Okay. So we fetched a number of logs from our server, IS logs, which are typical standards logging system and we downloaded a tool called JMeter. And JMeter is a Java-based tool which allows you to do things like load testing and so on. Nice thing about JMeter is that on high DPI screens, the UI is really, really small. But apart from that, it's actually a really cool tool because you can do things like replaying traffic. Let's open my test plan. It is as small for me as it is for you. Let's go in. Come on. Where did I put this document? There it is. We basically configured a test plan which would read our access logs from IS. So you basically tell this is my access log. You can read it from this specific path. Replay it against this server and then you can give it things like the number of users that you want to run against it, how you want to ramp up the number of users and so on. So to really reproduce the traffic your servers were seeing at a given time. So what we did was we looked into the logging. We decided on the window of the logs that we needed to replay this issue on our local machines and our dev environments and that's what we did. So thank you, JMeter for that. Your UI sucks but the tool is really, really awesome. So we did that and we went into the memory. Now, who of you would say they are really familiar with.NET memory management? Nobody? Good because I think nobody really is, not even the guys who wrote this thing. But I'll give you a quick introduction on how.NET memory management works so that you understand the problem we were seeing afterwards. So you replay the traffic but before we look at the results there's a couple of things you have to know. So in.NET as opposed to languages like C++ and so on, in.NET there's actually a run time, a managed run time that allocates memory for you if you need memory. In C++ what do you do? You tell the OS I need memory, they give you back an address in memory where you can store your stuff and if you don't free it you will get an out of memory situation because nobody is freeing up the memory for you. You have to really take care of that yourself. The way.NET works is whenever your application starts the run time asks the OS can you please allocate a big block of memory for me and I'll then in that block manage my own memory for you. So that's what.NET does and that big block of memory is the managed heap that you sometimes read about. Whenever you will instantiate a new object in.NET it gets allocated in this managed heap and that's really fast because you don't have to wait for the OS to give you access to a certain address..NET can basically tell you okay here's memory because it already has the memory available. Of course some unmanaged memory is also consumed like if you write a UI based application, WinForms or XAML or whatever you also get things like graphics buffers and things like that which are still unmanaged but most of the memory you are consuming in your.NET applications is this big chunk of data to manage to heap. Now whenever your variable goes out of scope and it's no longer needed you don't have to go and tell the OS to basically free the memory up again..NET will manage this for you. It will notice that the variable is out of scope. It will ignore that fact because it still has a big chunk of memory available so it will not free the memory immediately. What it will do is at a given point in time it will run the garbage collector. The garbage collector basically what it does is it scans this entire block of memory searches for variables that are no longer being used and then removes those from the managed block of memory so that the memory can be reused in future times. Now I said it scans the entire block of memory and that's quite an expensive operation to do. That's why.NET came up, well actually a lot of managed languages came up with the concept of generations in this garbage collector. Basically when you create a new variable or instantiate a new object or whatever the memory for that is allocated in Gen0 as it's called. Gen0 is where short lift objects go. Like in a method you create a string and two lines beyond that your method goes out of scope. Well that's Gen0 and it can be reclaimed really really fast because.NET knows that probably all the things in there or a lot of the things in there will probably be out of scope and can be recycled anyway. Except for the objects that cannot be recycled. Those are moved into Gen1. Gen1 is where medium lift objects live in.NET and.NET keeps them around until they are no longer needed in there as well. So the garbage collector mostly runs on Gen0. Every once in a while it runs on Gen1 to free the objects in there and if an object survives Gen1 it's moved into Gen2. So the really long lift objects. If we think back to our download counts example where we had this big dictionary of strings that were package IDs, inversions and download counts. That thing would probably be either Gen2 or the large memory heap because that's a long lift object. It lives the entire application lifetime and never gets to get recycled by the garbage collector. So that's basically how.NET works. It has these generations of memory and it frees the memory up for Gen0 mostly. Then every once in a while it does Gen1 as well and then even fewer times it does Gen2. Reason for that is if you have a long lift object there's no use in scanning this entire part of memory to free up memory because it's probably still in use. So that's how it works. So visually you first have your object in Gen0 then it moves to Gen1 if it's still alive. If not it's being reclaimed and memory is freed. If in Gen1 your object lives on it will go to Gen2. If not it will go out of Gen2. In Gen2 same thing if it keeps on being alive it will just remain in Gen2 until future collections. If it can be freed it will be freed eventually. Then there's another special case in this managed heap which is the large object heap. This is where large objects go. If you have an object of more than 85 kilobytes in memory size it goes into the large object heap because.NET thinks it's going to take a while to scan this entire object and make sure that I can reclaim it during a garbage collection cycle. It basically puts it there and that's where things don't have to end up ideally. But they go there. One issue with the large object heap there is if you have a lot of objects in there there's not a lot of optimization going on there by default which means that if you have a lot of objects in there you get fragmentation and you will get eventually out of memory exceptions. All right. Almost there. The.NET garbage collector is actually a really nice thing because to your application it looks like you have an infinite amount of memory. You just create new variables, create new objects, create whatever you want to create in your memory..NET will handle the memory for you and make sure there's always some memory available to do new things and your application doesn't have to care about what's happening in there. Now when does this garbage collector run? That's actually not really well documented. There's a couple of documents describing a lot of things but I don't think everything is documented. Since.NET Core, the garbage collector is actually open source so you can look in the sources but I think last time I checked it's a massive, I think it's around 37,000 lines of code doing the memory management. So if you can go in there and find out when the garbage collector runs please tell me. I would like to know. But from observation most people say okay it happens when there's an out of memory condition. When no memory is available in the managed heap, garbage collector will run and try to free up some resources in memory. After a significant allocation, again our download counts if we would allocate a new dictionary and populate this entire dictionary with 800,000 entries, we were seeing garbage collection there. Even in our profiler we were seeing garbage collection because of that. Also when it fails allocating resources it thinks okay maybe there's a memory issue here, let's optimize this. When you have a profiler attached or when you force it to do a garbage collection or when your application moves to the background. But the most important thing from all these observations is that the garbage collector is not guaranteed to run. If you have enough memory available for example it will run fewer times or maybe not run at all. Interesting, keep that in mind. Let's analyze our memory usage. So we replay traffic on our production instances and we got a memory snapshot. This is what we got. The gray part is the unmanaged memory that's being used. The green part, sorry the blue part is gen 0, the red part is gen 1 and the green part is gen 2. So what we can see in this diagram is actually quite interesting because we can see gen 2 is growing continuously. That's one thing. That's not ideal to be honest. What we can also see is that every time we take a snapshot in memory, memory pressure drops and we get some memory back so some garbage collection is happening which is a good thing. So let's dive into one of our snapshots and see what was in memory at that time. Now I'm going to take snapshot 6 and I'm going to take it for some reason. This is the reason. 2 million objects basically have been removed from memory when I took this snapshot which means the garbage collector did its work and what I will be able to see in this snapshot is probably what the garbage collector didn't collect and that's what we were interested in. So let's open this snapshot and wait until that memory shows us the things. It's actually a nice tool because it shows you some of the most common memory issues that you can have like duplicate strings or event handlers that you don't dispose of correctly and so on and you can dive into whatever is in there. At the bottom we can see the heaps and as I already said on the big chart we were seeing gen 2 was growing and growing and growing so let's see what's in gen 2. We can go in there and see which objects are in there and by default it will sort the objects by the number of retained bytes and that's basically the amount of bytes this object holds on to in other objects and this object is an inject.activation.caching.cache. Okay nice I cannot zoom there. I'll tell you there's one object of those which sort of speaks for itself with a cache. You have one cache holding on to a number of objects. The cache itself is only 48 bytes so nothing wrong there and it's keeping on or holding on to 90 megabytes of objects. Could be good, could be bad. So let's dive in. What's in this object? We see that it has some entries and these entries are an array that contain keys and values and items and it's basically easy to really get lost in this entire tree so that's not really useful information. So let's take one step back and look at this entire list one more time. Another object we see here is this guy. Of course there's a number of collections and things like that in our memory as well but what's interesting is that our entity framework context shows up as the sixth biggest object held in memory in this trace. Hmm fishy. Especially since it's in gen 2 because I would expect if I serve requests that have to make database calls we open an entity framework context, we handle the request, we close the entity framework context and it gets garbage collected in gen 0 or the latest in gen 1. Not in gen 2. What's even more interesting is that it's almost 80 megabytes of entity framework contexts floating around in memory. Fishy. So let's go in there. We see that there's a number of objects of this entity framework context. Let's group them by similar retention. Basically look at who is keeping this entity framework context in memory. What's the reason why this thing has not been garbage collected? Who is keeping this in memory? And the interesting thing is that we see our NINJECT cache showing up as the object holding on to our entity framework context. In fact it's holding on to 532 entity framework contexts in our gen 2 heap. Hmm. Alright. So our DI container, NINJECT at the time, seemed to be the reason why we had a lot of entity framework contexts still floating around in memory. So we decided, since NINJECT is open source, to go through the codes and see if we could find what was happening and why this was still being held in memory. And we found this garbage collection cache pruner. It was kept in memory by the cache and we find this cache pruner. So let's look at the code in there. It has, let me zoom in a little bit. Oh, that's fast. So fast. We live in the golden age of CPU cycles and this is still so fast. Anyway, this garbage collection cache pruner would actually make sure that our cache of objects that we instantiate through our DI container is every once in a while being cleaned up and the object it holds on to are being garbage collected. The way it does that is it has a weak reference and a weak reference is a type of object. If you instantiate it and the garbage collector runs, it will basically remove the reference so you know something has happened to it and someone has recycled this object so you know a garbage collection happens. It has a list of caches. It has a timer and a thread pool timer. Now, the interesting thing is whenever the timer runs, which is every, I think, 30 seconds it was by default, it would purge prune cache if garbage collector has run. Okay, let's go there. Prune cache if garbage collector has run. If you are on a PCL, you are unlucky. If not, we would lock. We would check if our indicator, our weak reference has been collected or not. If it hasn't been collected, we just return and don't clear our cache. Okay, remember that the garbage collector is not guaranteed to run? That's the reason this variable was not collected and that's the reason why this timer would eventually just return every single time and just keep all the objects that it caches in its internal cache floating around and basically exhaust our memory continuously. So, yeah, Ninject was not very friendly to us and we found some other people with exactly the same issue and no fix yet. So, the thing we did was we changed to a different TI container, autofack in this case. We ran the new analysis and we saw that response times dropped tremendously, first of all. So, it was faster than Ninject as well and our memory issue was also gone and we are now stable at a 4 gigabytes memory usage overall on our compute nodes there. So, that's really, really nice improvement. Case closed. So, in conclusion, when you start debugging and when you start spelunking an entire chain of possible bugs that follow one after another, you will have to build some familiarity with your system that you are trying to debug and trying to investigate. Try to, in your mind, think like the compiler, think like.NET's garbage collector, think like whatever can happen in your own codes and that will really help you finding these issues. Bugs hides and we found out that whenever we fixed a bug, there would be a new bug popping up because we fixed the original bug and we would just open the floodgates to the new one. So, keep that in mind if you fix this type of issues, you may run into the next one the next day or even the next hour. What I did learn from this experience, I've been doing this for three, four months, this entire thing, what I did learn is that I learned a lot about how.NET works and I learned that I actually like spelunking through memory traces, through performance, snapshot sense and so on because you learn how your code is behaving even better, you learn how the.NET framework is behaving in the different versions of the.NET framework and you overall build experience for the next bug that comes along. So, if you have an issue like this, don't go, it's an ops problem, dive in and try and investigate, it's really, really useful to do. With that, thank you for being here and enjoy the rest of NDC.
and we had to find out what was the cost of this maybe SQL. We looked at search. We have some enough traffic and the CPU was idling because the search service. I have those traces as well. on any IIS web server you can go there, you will So we fetched a number of logs from our server, you have a profiler attached or when you force it analyze our memory usage. So we replay traffic on in there and see which objects are in there and