{"id":14904,"date":"2022-10-17T12:00:00","date_gmt":"2022-10-17T11:00:00","guid":{"rendered":"https:\/\/exa.net.uk\/?p=14904"},"modified":"2024-05-15T17:04:06","modified_gmt":"2024-05-15T16:04:06","slug":"latency-debugging","status":"publish","type":"post","link":"https:\/\/edit.exa.net.uk\/knowledge-hub\/technical\/latency-debugging\/","title":{"rendered":"Debugging Latency on 40 SurfProtect servers"},"content":{"rendered":"\t\t
\n\t\t\t\t\t\t
\n\t\t\t\t\t\t
\n\t\t\t\t\t
\n\t\t\t
\n\t\t\t\t\t\t
\n\t\t\t\t
\n\t\t\t\t\t
\n\t\t\t\n\t\t\t\t\t\t\n\t\t\t\t\t\t\n\t\t\t\t<\/i>\t\t\t<\/span>\n\t\t\t\t\t\t\t\t\tKnowledge Hub<\/span>\n\t\t\t\t\t<\/span>\n\t\t\t\t\t<\/a>\n\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
\n\t\t\t\t
\n\t\t\t

Knowledge Hub<\/span>TM<\/sup>\"\"<\/span><\/h2>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
\n\t\t\t\t
\n\t\t\t

Debugging Latency on 40 SurfProtect servers<\/h1>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
\n\t\t\t\t
\n\t\t\t\t\t
\n\t\t\t
<\/div>\n\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
\n\t\t\t\t
\n\t\t\t\t\t
    \n\t\t\t\t\t\t\t\t
  • \n\t\t\t\t\t\t\t\t\t\t\t\t\t\n\t\t\t\t\t\t\tDate Posted:<\/span>\n\t\t\t\t\t\t\t\t\t\t
  • \n\t\t\t\t\t\t\t\t\t\t\t\t\t\n\t\t\t\t\t\t\tRead time:<\/span>\n\t\t\t\t\t\t\t\t\t\t\n\t\t\t\t11 min read<\/span>\t\t\t\t<\/span>\n\t\t\t\t\t<\/span>\n\t\t\t\t\t\t\t\t<\/li>\n\t\t\t\t
  • \n\t\t\t\t\t\t\t\t\t\t\t\t\t\n\t\t\t\t\t\t\tWritten by:<\/span>\n\t\t\t\t\t\t\t\t\t\tExa Networks\t\t\t\t\t<\/span>\n\t\t\t\t\t\t\t\t<\/li>\n\t\t\t\t<\/ul>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
    \n\t\t\t\t
    \n\t\t\t\t\t
    \n\t\t\t
    <\/div>\n\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/section>\n\t\t\t\t
    \n\t\t\t\t\t\t
    \n\t\t\t\t\t
    \n\t\t\t
    \n\t\t\t\t\t\t
    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    For the past couple of weeks, our active monitoring detected several occasions where the latency of traffic going through our SurfProtect service increased significantly enough to be worthy of investigation.<\/h4>

    At the outset of the investigation, when our monitoring tools first identified the problem, the effect on our customers was not pronounced enough to be noticeable. But our team discovered that the issue was persistent and that the problem never seemed to be accompanied or preceded by any change in traffic patterns or other services that might explain them.<\/p>

    Unfortunately, the problem became service-affecting before we were able to resolve it. This article explains what happened, why and how we were able to restore services to their normal service level.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t

    Investigating the reason for the slowdown<\/h2>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    Investigating our code<\/h3>

    SurfProtect is a complex application provided by over 40 servers, 16 of which are proxies taking customers’ HTTP and HTTPS requests, accepting or blocking them.<\/p>

    Our service monitoring includes exporting information about the response time of different components. Looking at this data, we could see that we were making filtering decisions promptly and that the cause of the latency was within our proxy code, which was surprising as this code had been stable and well-behaved for a few years.<\/p>

    Our proxies are written in Go, a language designed by Google to develop high-concurrency applications such as our proxy. This language comes with excellent real-time debugging tools, which we have come to master.<\/p>

    The team used them to seek to understand the reason for the slowdown. Unfortunately, following our initial research, we could only establish that the SurfProtect proxy process was taking longer and longer as time went on, waiting for the OS to respond to network reads and writes.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t\t\t
    \n\t\t\t\t\t
    \n\t\t\t
    \n\t\t\t\t\t\t
    \n\t\t\t\t
    \n\t\t\t\t\t\t\t\t\t\t\t\t\t\"\"\t\t\t\t\t\t\t\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/div>\n\t\t\t\t
    \n\t\t\t
    \n\t\t\t\t\t\t
    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    The image on the left is an excerpt from a visualisation we use to understand where the application spends most of its time.<\/p>

    This particular data comes from one of the incidents where latency on a machine rose by about 100ms. Average samples were showing CPU usage of around 40% performing the same tasks, compared to our expectation of 25% during standard operation.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/section>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    89.58% of our available CPU resources were spent waiting for the OS to respond to read and write operations to the network.<\/span>
    <\/p>\n

    This meant that the remaining 75% of the work usually performed by the proxy, was being performed with the remaining 10.42% of resources available on the machine.<\/p>\n

    Our team started to look into what could have caused this behaviour change.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    Investigating CPU usage<\/h3>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
    \n\t\t\t\t
    \n\t\t\t\t\t\t\t\t\t\t\t\t\t\"\"\t\t\t\t\t\t\t\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
    \n\t\t\t\t
    \n\t\t\t\t\t\t\t
    Looking at the CPU usage graph illustrates the issue. The CPU time allocated to the proxy service (in yellow) became negligible compared to the time spent within the Operating System (in blue). We also expect this class of machine to show far lower CPU usage at such relatively low bandwidth usage.<\/span><\/h5>

    As the proxy processes are allowed to use (up to) all of the cores on one of the two processors present, it’s clear from the flat line at 60% overall usage that we had hit a resource contention which led to the latency issue we experienced.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t

    The search for the root cause\n<\/h2>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t
    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    Our team then realised that we needed to change our perspective and identified two independent courses of action to push us towards a resolution.<\/p>

    Right from the start of the incident, our tools functioned as we hoped, alerting us to high latency and abnormal resource usage, recording when they occurred, and highlighting the reason for the latency with the proxy’s code. Still, we had no visibility of what was happening inside the kernel. We could not explain why we were experiencing high CPU usage.<\/p>

    By and large, our monitoring focuses on the service we provide and allows us to inspect the behaviour of our software. We’re usually happy to rely on the Linux kernel to do its job after we’ve been through the process of validating during testing and through progressive acceptance in service that it can support the features we use.<\/p>

    Based on our deployment experience, we have a good idea of how a machine will respond to certain types of workload and the states of its various subsystems. We have a broad understanding of how Linux subsystems are implemented, but in this occurrence we were initially frustrated. None of the information generated seemed to suggest a reason for the issues. Nothing had changed since the end of the previous school year, which had seen much higher traffic volume per service. We deployed more machines during the summer, so the traffic and CPU load per machine should be lower, not higher. Nothing related to networking on the servers also looked out of place.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    Facilitating the gathering of data<\/h3>

    We needed to extend our monitoring to the Linux kernel during outages. We realised our team already had a documented way to gather this data during investigations, but we were missing a quick and easy mechanism to standardise the data collected. We decided to put together new tools to gather the information we thought would help our engineers.<\/p>

    But we had to be careful: some of the mechanisms required to gather this information were already running at high CPU levels, and our actions could impact normal operations. We could not leave this running permanently but had to wait for an incident to collect the data.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    Investigating Linux<\/h3>

    As the problem was not within our code, our first course of action was to ensure that we were not potentially affected by recently released and misbehaving drivers or firmware.<\/p>

    We then debated between rolling back an older version or updating it to a new version of the kernel just released a few days earlier. We decided to update first instead of downgrading: even if downgrading could resolve the issue, it would prevent us from diagnosing the problem. We were unsure we could replicate the issue in our test environment, and holding back the machines’ kernel version was not a long-term solution. However, it happened that we found the reason for this behaviour before we could roll back.<\/p>

    We also saw to determine if we could correlate at least the most severe incidents to any particular hardware vendor. During our investigation, it became clear that our newly encountered OS problems were happening across the different generations of machine and networking cards. Upon investigation, we could not trace the faulty behaviour to any specific software, firmware or hardware combination.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    Diving deeper<\/h3>

    While our investigations and new tool development took place, we also had to investigate the possibility of a non-hardware-related issue with the Linux kernel.<\/p>

    As pointed out above, right at the start of the investigation, we identified an issue with Linux system calls while reading and writing to the network. We decided that we needed to understand what exactly Linux was doing while handling our IO requests. If we could see pauses while writing to or reading from network cards, it would confirm a possible driver issue; otherwise, it should give us food for thought and allow us to move forward.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t\t\t\t\t

    So the team turned to the ‘perf’ tool to investigate why system calls took so long to return.<\/p>

    Due to initial unfamiliarity with the ‘perf’ tool, we went straight to the interface provided by debugfs and used by ‘perf’ for this purpose. Once understood, acquiring the data we wanted could not have been simpler:<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t

    \n\t\t\t\t
    \n\t\t\t\t\t
    \n\t\t\t
    \n\t\t\t\t\n\t\t\t\t\techo \"function_graph\" >  \/sys\/kernel\/debug\/tracing\/current_tracer\necho 1 >  \/sys\/kernel\/debug\/tracing\/tracing_on\ncat \/sys\/kernel\/debug\/tracing\/trace > trace\n<\/xmp>\n\t\t\t\t<\/code>\n\t\t\t<\/pre>\n\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-3a5dd022 elementor-widget elementor-widget-text-editor\" data-id=\"3a5dd022\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<p>While our worries eventually proved unwarranted, the data initially made us wonder if we were monitoring contention within the tracer code. So, we limited the monitoring to only one core to limit the likelihood of going down a false track:<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-5899c6e3 elementor-widget elementor-widget-code-highlight\" data-id=\"5899c6e3\" data-element_type=\"widget\" data-widget_type=\"code-highlight.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t<div class=\"prismjs-default copy-to-clipboard \">\n\t\t\t<pre data-line=\"\" class=\"highlight-height language-go line-numbers\">\n\t\t\t\t<code readonly=\"true\" class=\"language-go\">\n\t\t\t\t\t<xmp>echo \"00000000,00000000,01000000\" > \/sys\/kernel\/debug\/tracing\/tracing_cpumask\n<\/xmp>\n\t\t\t\t<\/code>\n\t\t\t<\/pre>\n\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-6ae7ceb2 elementor-widget elementor-widget-text-editor\" data-id=\"6ae7ceb2\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<p>This command provided us with a\u00a0<em>very<\/em>\u00a0detailed trace of precisely what was going on, along with high-resolution timing information showing how long everything was taking. It was perfect, or almost perfect, since enabling the tracer saw CPU usage jump, and we could not accurately collect data from a machine exhibiting the problem. Still, the data gathered was enough to identify a specific issue conclusively.<\/p><p>Our analysis focused on the kernel function\u00a0<code>do_syscall_64<\/code>, used by the IO calls. The data indicated that most calls returned within a perfectly reasonable time but that some calls inexplicably took 10s to 100s of milliseconds, matching what we&#8217;d already observed with the output of &#8216;perf&#8217;.<\/p><p>Further analysis showed an interesting pattern that occurred in &#8216;slow&#8217; calls:<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-33427634 elementor-widget elementor-widget-code-highlight\" data-id=\"33427634\" data-element_type=\"widget\" data-widget_type=\"code-highlight.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t<div class=\"prismjs-default copy-to-clipboard \">\n\t\t\t<pre data-line=\"\" class=\"highlight-height language-go line-numbers\">\n\t\t\t\t<code readonly=\"true\" class=\"language-go\">\n\t\t\t\t\t<xmp>kprobe_ftrace_handler() {\n 93)   0.140 us    |          get_kprobe();\n 93)               |          pre_handler_kretprobe() {\n 93)   0.150 us    |            _raw_spin_lock_irqsave();\n 93)   0.150 us    |            _raw_spin_unlock_irqrestore();\n 93)   0.150 us    |            arch_prepare_kretprobe();\n 93)               |            _raw_spin_lock_irqsave() {\n 93) # 1459.327 us |              native_queued_spin_lock_slowpath();\n 93) # 1460.008 us |            }\n 93)               |            _raw_spin_unlock_irqrestore() {```\n<\/xmp>\n\t\t\t\t<\/code>\n\t\t\t<\/pre>\n\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-5e1370cc elementor-widget elementor-widget-text-editor\" data-id=\"5e1370cc\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<p>and<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-1d98a19b elementor-widget elementor-widget-code-highlight\" data-id=\"1d98a19b\" data-element_type=\"widget\" data-widget_type=\"code-highlight.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t<div class=\"prismjs-default copy-to-clipboard \">\n\t\t\t<pre data-line=\"\" class=\"highlight-height language-go line-numbers\">\n\t\t\t\t<code readonly=\"true\" class=\"language-go\">\n\t\t\t\t\t<xmp> 79)               |        trampoline_handler() {\n 79)   0.140 us    |          kprobe_busy_begin();\n 79)               |          kretprobe_hash_lock() {\n 79)   0.150 us    |            _raw_spin_lock_irqsave();\n 79)   0.411 us    |          }\n 79)   0.140 us    |          percpu_array_map_lookup_elem();\n 79)   0.140 us    |          percpu_array_map_lookup_elem();\n 79)   0.140 us    |          bpf_get_current_pid_tgid();\n 79)               |          __htab_map_lookup_elem() {\n 79)   0.150 us    |            lookup_nulls_elem_raw();\n 79)   0.652 us    |          }\n 79)               |          htab_map_update_elem() {\n 79)               |            _raw_spin_lock_irqsave() {\n 79) # 1433.058 us |              native_queued_spin_lock_slowpath();\n 79) # 1434.020 us |            }\n<\/xmp>\n\t\t\t\t<\/code>\n\t\t\t<\/pre>\n\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-5d9d54e0 elementor-widget elementor-widget-text-editor\" data-id=\"5d9d54e0\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<p>This information allowed us to establish where the CPU spent its time. Rather than just checking in periodically with the network hardware, the kernel attempted to acquire a lock rather than doing valuable work.<\/p><p>We were now looking in the right place, but most calls to\u00a0<code>do_syscall_64<\/code>\u00a0were reasonably fast, so we used the data to generate a flame graph to better understand the scale of the problem. It provided rather convincing evidence to support our belief that there was an issue with our newer kernel:<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-64040cd2 dce_masking-none elementor-widget elementor-widget-image\" data-id=\"64040cd2\" data-element_type=\"widget\" data-widget_type=\"image.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t\t\t\t\t\t\t<img decoding=\"async\" width=\"1024\" height=\"841\" src=\"https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-before-1024x841.png\" class=\"attachment-large size-large wp-image-15001\" alt=\"\" srcset=\"https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-before-1024x841.png 1024w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-before-300x246.png 300w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-before-768x631.png 768w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-before.png 1199w\" sizes=\"(max-width: 1024px) 100vw, 1024px\" title=\"\">\t\t\t\t\t\t\t\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-5cfcbd32 elementor-widget elementor-widget-text-editor\" data-id=\"5cfcbd32\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<p>The server was performing minimum work; the CPU core was busy acquiring a spinlock for about 1\/3 of the available time. As we had established that the proportion of &#8216;wasted&#8217; time grew as the problem worsened, we could now explain this behaviour as increased contention as threads become more likely to vie for the shared resource.<\/p><p>We now knew that we were putting effort into the right place and went back to the analysis of the kernel trace. We were relieved when we tied the problem behaviour ultimately to calls to\u00a0<code>security_socket_sendmsg<\/code>, which in turn calls\u00a0<code>apparmor_socket_sendmsg<\/code>.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-37b75dcc elementor-widget elementor-widget-heading\" data-id=\"37b75dcc\" data-element_type=\"widget\" data-widget_type=\"heading.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t<h2 class=\"elementor-heading-title elementor-size-default\">Resolution\n<\/h2>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-60136444 elementor-widget elementor-widget-text-editor\" data-id=\"60136444\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<h3 id=\"finding-the-change\">Finding the change<\/h3><p>AppArmor is a Mandatory Access Control (MAC) system that provides fine-grained access rights to resources within the kernel. Like sandboxing, it can limit what an application can and can not do on the server.<\/p><p>This Linux feature is handy when running untrusted programs and is used on our customer web servers. However, it does not achieve much on our proxies that only run our proprietary software, where we are in a position to use coarser mechanisms to provide privilege separation and security. It left us with the straightforward option of removing AppArmor from the affected machines as it consists of kernel features which are enabled from some userland programs.<\/p><p>The removal was first performed on one server at approx 12:50 on Thursday, 14th October. We removed the Linux AppArmor package from the machine and rebooted the server. We then migrated some customer traffic to the machine and noted no sign of increased latency. Another maintenance was therefore scheduled for the evening to roll this change out across all servers in the cluster.<\/p><p>While we have not yet conclusively linked the periods of severe latency to the persistent issues that were the focus of our investigation, CPU usage has remained stable since this maintenance, and we have detected no further anomalous latency. The below CPU-usage graph shows that the previously struggling server is now able to handle the same level of traffic with much-reduced CPU usage:<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-6a0b68f3 dce_masking-none elementor-widget elementor-widget-image\" data-id=\"6a0b68f3\" data-element_type=\"widget\" data-widget_type=\"image.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t\t\t\t\t\t\t<img loading=\"lazy\" decoding=\"async\" width=\"1024\" height=\"218\" src=\"https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/cpu-system-after-1024x218.png\" class=\"attachment-large size-large wp-image-15007\" alt=\"\" srcset=\"https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/cpu-system-after-1024x218.png 1024w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/cpu-system-after-300x64.png 300w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/cpu-system-after-768x163.png 768w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/cpu-system-after-1536x327.png 1536w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/cpu-system-after.png 1815w\" sizes=\"(max-width: 1024px) 100vw, 1024px\" title=\"\">\t\t\t\t\t\t\t\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-2761ebbb elementor-widget elementor-widget-text-editor\" data-id=\"2761ebbb\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<p>(NB: the periodic spikes in CPU usage are expected behaviour caused by memory garbage collection within our proxy process and do not contribute to latency.)<\/p><p>We also see in our flame graph that there&#8217;s no longer any sign of the CPU wasting cycles in a spin lock:<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-3b569a16 dce_masking-none elementor-widget elementor-widget-image\" data-id=\"3b569a16\" data-element_type=\"widget\" data-widget_type=\"image.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t\t\t\t\t\t\t<img loading=\"lazy\" decoding=\"async\" width=\"1024\" height=\"851\" src=\"https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-after-1024x851.png\" class=\"attachment-large size-large wp-image-15011\" alt=\"\" srcset=\"https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-after-1024x851.png 1024w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-after-300x249.png 300w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-after-768x639.png 768w, https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2022\/11\/kernel-flame-after.png 1199w\" sizes=\"(max-width: 1024px) 100vw, 1024px\" title=\"\">\t\t\t\t\t\t\t\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-3520f3bd elementor-widget elementor-widget-text-editor\" data-id=\"3520f3bd\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<h3 id=\"detection\">Detection<\/h3><p>The instant we confirmed that disabling AppArmor appeared to fix the issue, team members were on hand to tell us that the package provided the affected code had last been updated by our Linux vendor as part of their security updates on the 31st of August 2022.<\/p><p>It was initially confusing since there was no sign of the issue for weeks when the school year started. As the behaviour changes on servers after a reboot, and since the contention seems to only occur once the level of traffic saturates the CPU, it wasn&#8217;t clear from our monitoring that affected machines had recently been rebooted. We only reboot the machine to apply kernel when the update fixes security issues and not generic problems, as our proxies have to run for long periods with no downtime.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-64d5bc54 elementor-widget elementor-widget-text-editor\" data-id=\"64d5bc54\" data-element_type=\"widget\" data-widget_type=\"text-editor.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t\t\t<h3 id=\"looking-forward\">Looking Forward<\/h3><p>We have monitoring in place to track the running version of our own software, but this doesn&#8217;t yet extend to tracking the running kernel version or the versions of any modules that may impact us.<\/p><p>We will update our operating procedure to track our active cluster members&#8217; kernel version and machine uptime. From now on, we should be able to identify better when changes have delayed consequences more easily.<\/p><p>And following this work, our new tool will continue to evolve and help us gather more data from our cluster of SurfProtect servers.<\/p>\t\t\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<section class=\"has_eae_slider elementor-section elementor-inner-section elementor-element elementor-element-306a1079 elementor-section-content-middle elementor-section-boxed elementor-section-height-default elementor-section-height-default\" data-id=\"306a1079\" data-element_type=\"section\" data-settings=\"{&quot;jet_parallax_layout_list&quot;:[{&quot;_id&quot;:&quot;62e95af&quot;,&quot;jet_parallax_layout_image&quot;:{&quot;url&quot;:&quot;&quot;,&quot;id&quot;:&quot;&quot;,&quot;size&quot;:&quot;&quot;},&quot;jet_parallax_layout_image_tablet&quot;:{&quot;url&quot;:&quot;&quot;,&quot;id&quot;:&quot;&quot;,&quot;size&quot;:&quot;&quot;},&quot;jet_parallax_layout_image_mobile&quot;:{&quot;url&quot;:&quot;&quot;,&quot;id&quot;:&quot;&quot;,&quot;size&quot;:&quot;&quot;},&quot;jet_parallax_layout_speed&quot;:{&quot;unit&quot;:&quot;%&quot;,&quot;size&quot;:50,&quot;sizes&quot;:[]},&quot;jet_parallax_layout_type&quot;:&quot;scroll&quot;,&quot;jet_parallax_layout_direction&quot;:null,&quot;jet_parallax_layout_fx_direction&quot;:null,&quot;jet_parallax_layout_z_index&quot;:&quot;&quot;,&quot;jet_parallax_layout_bg_x&quot;:50,&quot;jet_parallax_layout_bg_x_tablet&quot;:&quot;&quot;,&quot;jet_parallax_layout_bg_x_mobile&quot;:&quot;&quot;,&quot;jet_parallax_layout_bg_y&quot;:50,&quot;jet_parallax_layout_bg_y_tablet&quot;:&quot;&quot;,&quot;jet_parallax_layout_bg_y_mobile&quot;:&quot;&quot;,&quot;jet_parallax_layout_bg_size&quot;:&quot;auto&quot;,&quot;jet_parallax_layout_bg_size_tablet&quot;:&quot;&quot;,&quot;jet_parallax_layout_bg_size_mobile&quot;:&quot;&quot;,&quot;jet_parallax_layout_animation_prop&quot;:&quot;transform&quot;,&quot;jet_parallax_layout_on&quot;:[&quot;desktop&quot;,&quot;tablet&quot;]}]}\">\n\t\t\t\t\t\t<div class=\"elementor-container elementor-column-gap-default\">\n\t\t\t\t\t<div class=\"has_eae_slider elementor-column elementor-col-50 elementor-inner-column elementor-element elementor-element-2f96de0b\" data-id=\"2f96de0b\" data-element_type=\"column\">\n\t\t\t<div class=\"elementor-widget-wrap elementor-element-populated\">\n\t\t\t\t\t\t<div class=\"elementor-element elementor-element-57c995e0 next-read-section elementor-widget elementor-widget-heading\" data-id=\"57c995e0\" data-element_type=\"widget\" data-widget_type=\"heading.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t<p class=\"elementor-heading-title elementor-size-default\"><span class=\"lightblue\">Suggested<\/span> Next Read <span class=\"lightblue\"><i class=\"fas fa-caret-right\"><\/i><\/span><\/p>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/div>\n\t\t\t\t<div class=\"has_eae_slider elementor-column elementor-col-50 elementor-inner-column elementor-element elementor-element-4ae5de96\" data-id=\"4ae5de96\" data-element_type=\"column\">\n\t\t\t<div class=\"elementor-widget-wrap elementor-element-populated\">\n\t\t\t\t\t\t<div class=\"elementor-element elementor-element-d8dcf6f custom-slider blog-slide custom-slider-green elementor-widget__width-initial elementor-widget elementor-widget-ucaddon_uc_card_post_carousel_blog\" data-id=\"d8dcf6f\" data-element_type=\"widget\" data-widget_type=\"ucaddon_uc_card_post_carousel_blog.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\n<!-- start Card Post Carousel - Blog -->\n\t\t<link id='font-awesome-css' href='https:\/\/edit.exa.net.uk\/wp-content\/plugins\/unlimited-elements-for-elementor\/assets_libraries\/font-awesome6\/fontawesome-all.min.css' type='text\/css' rel='stylesheet' >\n\t\t<link id='font-awesome-4-shim-css' href='https:\/\/edit.exa.net.uk\/wp-content\/plugins\/unlimited-elements-for-elementor\/assets_libraries\/font-awesome6\/fontawesome-v4-shims.min.css' type='text\/css' rel='stylesheet' >\n\t\t<link id='owl-carousel-css' href='https:\/\/edit.exa.net.uk\/wp-content\/plugins\/unlimited-elements-for-elementor\/assets_libraries\/owl-carousel\/assets\/owl.carousel.css' type='text\/css' rel='stylesheet' >\n\n<style>\/* widget: Card Post Carousel - Blog *\/\n\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f *{\n  box-sizing:border-box;\n}\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f{\n  position:relative;\n}\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f .uc_image_carousel_content{\n\ttext-align:left;\n    display: flex;\n     flex-flow: column nowrap;\n}\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f .ue_post_carousel_item\n{\n  overflow:hidden;\n  \n}\n\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f .ue_post_btn_holder\n{\n  margin-top:auto;\n}\n\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f .uc_more_btn{\n\n  display:inline-block;\n  text-align:center;\n  text-decoration:none;\n} \n\n.uc_overlay_image_carousel .uc_more_btn{\n  text-decoration:none;\n  display:inline-block;\n}\n\n.uc_overlay_image_carousel .uc_post_title{\n  font-size:21px;\n  text-decoration:none;\n}\n\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f .owl-nav .owl-prev{\n    position:absolute;\n    left:-40px;\n    display:inline-block;\n    text-align:center;\n}\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f .owl-nav .owl-next{\n  position:absolute;\n    right:-40px;\n  display:inline-block;\n  text-align:center;\n}\n\n\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f .owl-dots {\noverflow:hidden;\ndisplay:false !important;\ntext-align:center;\n}\n\n#uc_uc_card_post_carousel_blog_elementor_d8dcf6f .owl-dot {\nborder-radius:50%;\ndisplay:inline-block;\n}\n\n<\/style>\n\n<div class=\"uc_overlay_image_carousel\" id=\"uc_uc_card_post_carousel_blog_elementor_d8dcf6f\" style=\"direction:ltr;\">\n   <div class=\"uc_carousel owl-carousel owl-theme\">\n   \t\t<div class=\"uc_image_carousel_container_holder ue_post_carousel_item\">\n  <div class=\"uc_image_carousel_placeholder\">\n    <a href=\"https:\/\/edit.exa.net.uk\/knowledge-hub\/technical\/ensuring-robust-security-through-regular-firewall-updates\/\">\n\t\t\n      <div class=\"custom-slider-bg\" style=\"background-image:url(https:\/\/edit.exa.net.uk\/wp-content\/uploads\/2021\/03\/fortinet-logo.svg); background-size:cover; background-position:center; height:115px;\">\n\t\t<div class=\"color-bg\">\n\t\t\t<div class=\"content-info\">\n\t\t\t\t<a href=\"https:\/\/edit.exa.net.uk\/knowledge-hub\/technical\/ensuring-robust-security-through-regular-firewall-updates\/\" style=\"text-decoration:none;\"><div class=\"uc_post_title\" style=\"text-decoration:none;\">Ensuring Robust Security Through Regular Firewall Updates<\/div><\/a>\t\t\t<\/div>\n\t\t\n\t\t<\/div>\n      <\/div>\n\t<\/a>\n  <\/div>\n\n  <div class=\"uc_image_carousel_content\" >\n    <a class=\"post-link\" href=\"https:\/\/edit.exa.net.uk\/knowledge-hub\/technical\/ensuring-robust-security-through-regular-firewall-updates\/\">Read Next<\/a>  <\/div>\n<\/div>\n\n   <\/div>\t\n<\/div>\n<!-- end Card Post Carousel - Blog -->\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/section>\n\t\t\t\t<div class=\"elementor-element elementor-element-56c79c98 elementor-widget__width-initial elementor-hidden-phone elementor-widget elementor-widget-spacer\" data-id=\"56c79c98\" data-element_type=\"widget\" data-widget_type=\"spacer.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t\t\t<div class=\"elementor-spacer\">\n\t\t\t<div class=\"elementor-spacer-inner\"><\/div>\n\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/div>\n\t\t\t\t<div class=\"has_eae_slider jet-sticky-column elementor-column elementor-col-50 elementor-top-column elementor-element elementor-element-52f48463\" data-jet-settings=\"{&quot;id&quot;:&quot;52f48463&quot;,&quot;sticky&quot;:true,&quot;topSpacing&quot;:155,&quot;bottomSpacing&quot;:50,&quot;stickyOn&quot;:[&quot;desktop&quot;,&quot;tablet&quot;]}\" data-id=\"52f48463\" data-element_type=\"column\">\n\t\t\t<div class=\"elementor-widget-wrap elementor-element-populated\">\n\t\t\t\t\t\t<div class=\"elementor-element elementor-element-5b42788c elementor-widget elementor-widget-heading\" data-id=\"5b42788c\" data-element_type=\"widget\" data-widget_type=\"heading.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t<h2 class=\"elementor-heading-title elementor-size-default\"><span class=\"lightblue\">Related<\/span> Knowledge <span class=\"lightblue\">Hub<\/span>&trade; Articles<\/h2>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-613dd224 elementor-grid-1 elementor-grid-tablet-1 elementor-posts--thumbnail-top elementor-grid-mobile-1 elementor-widget elementor-widget-posts\" data-id=\"613dd224\" data-element_type=\"widget\" data-settings=\"{&quot;custom_columns&quot;:&quot;1&quot;,&quot;custom_row_gap&quot;:{&quot;unit&quot;:&quot;px&quot;,&quot;size&quot;:25,&quot;sizes&quot;:[]},&quot;custom_columns_tablet&quot;:&quot;1&quot;,&quot;custom_columns_mobile&quot;:&quot;1&quot;,&quot;custom_row_gap_tablet&quot;:{&quot;unit&quot;:&quot;px&quot;,&quot;size&quot;:&quot;&quot;,&quot;sizes&quot;:[]},&quot;custom_row_gap_mobile&quot;:{&quot;unit&quot;:&quot;px&quot;,&quot;size&quot;:&quot;&quot;,&quot;sizes&quot;:[]}}\" data-widget_type=\"posts.custom\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t      <div class=\"ecs-posts elementor-posts-container elementor-posts   elementor-grid elementor-posts--skin-custom\" data-settings=\"{&quot;current_page&quot;:1,&quot;max_num_pages&quot;:0,&quot;load_method&quot;:&quot;&quot;,&quot;widget_id&quot;:&quot;613dd224&quot;,&quot;post_id&quot;:14904,&quot;theme_id&quot;:14904,&quot;change_url&quot;:false,&quot;reinit_js&quot;:false}\">\n      <div class=\"elementor-posts-nothing-found\"><\/div>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t<div class=\"elementor-element elementor-element-6bf5c137 next-read-section elementor-widget elementor-widget-heading\" data-id=\"6bf5c137\" data-element_type=\"widget\" data-widget_type=\"heading.default\">\n\t\t\t\t<div class=\"elementor-widget-container\">\n\t\t\t<p class=\"elementor-heading-title elementor-size-default\"><a href=\"https:\/\/exa.net.uk\/knowledge-hub\/\" target=\"_blank\" rel=\"noopener\">Knowledge <span class=\"lightblue\">Hub<\/span>&trade; <span class=\"lightblue\">Home<\/span> <i class=\"fas fa-chevron-right\"><\/i><\/a><\/p>\t\t<\/div>\n\t\t\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/div>\n\t\t\t\t\t<\/div>\n\t\t<\/section>\n\t\t\t\t<\/div>\n\t\t","protected":false},"excerpt":{"rendered":"<p>Knowledge Hub Knowledge HubTM For the past couple of weeks, our active monitoring detected several occasions where the latency of traffic going through our SurfProtect service increased significantly enough to be worthy of investigation. At the outset of the investigation, when our monitoring tools first identified the problem, the effect on our customers was not &#8230; <a title=\"Debugging Latency on 40 SurfProtect servers\" class=\"read-more\" href=\"https:\/\/edit.exa.net.uk\/knowledge-hub\/technical\/latency-debugging\/\" aria-label=\"Read more about Debugging Latency on 40 SurfProtect servers\">Read more<\/a><\/p>\n","protected":false},"author":4,"featured_media":15205,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"elementor_header_footer","format":"standard","meta":{"rank_math_lock_modified_date":false,"footnotes":""},"categories":[73],"tags":[29],"class_list":["post-14904","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-technical","tag-11-min-read"],"_links":{"self":[{"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/posts\/14904","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/users\/4"}],"replies":[{"embeddable":true,"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/comments?post=14904"}],"version-history":[{"count":1,"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/posts\/14904\/revisions"}],"predecessor-version":[{"id":24013,"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/posts\/14904\/revisions\/24013"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/media\/15205"}],"wp:attachment":[{"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/media?parent=14904"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/categories?post=14904"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/edit.exa.net.uk\/wp-json\/wp\/v2\/tags?post=14904"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}