Advanced Strategies for Precise and Transparent Debugging of Performance Issues in In-Memory Data Store-Based Microservices

This subsection describes how events are handled in a trace, to build a model as defined in Section III-C.

Consider a Redis client that transmits a request to publish particular data on a channel, to exemplify one facet on how the analysis operates. Figure 4 illustrates the outcomes of the analysis performed on the trace.

To run a command, the client establishes a connection with the server. The polling phase is executed on the Redis server side, during which the EL is notified of an incoming event on the socket. Following this, the start_read_client_query tracepoint is triggered.

During the trace analysis, the algorithm extracts the FD, the timestamp, and the thread ID immediately upon encountering this event. Subsequently, it stores these values in the SHT. In the model, Connection and Requests branches are instantiated.

The FD is added to the data structure resource in the Connexion branch in the SHT, at that timestamp. Based on the FD, in the connection context, the Memory resource is populated with the value of the consumed memory, as determined by the event attributes.

The Type attribute of the corresponding resource is set to ”client” in order to denote that the connection pertains to a client link. The FD is also added to the Connection resource within the Requests branch in the SHT, along with the timestamp extracted from the attributes.

Prior to encountering the end_read_client_query event, indicating that the incoming event has been read from the connection, the algorithm watches the call_command_start event. The latter enables the decoding of the pending command and the invocation of the Redis function that is accountable for carrying out the execution. The timestamp and the command name are obtained by extracting the attributes from this event.

The automaton then enters the ”publish” state, as depicted in Figure 4. As the analysis progresses, it encounters the serial add_file_event event, prior to reaching the call_command_end event. The add_file_event tracepoint instruments the queuing process of the event, for its execution in the subsequent phase of the EL.

The analysis then updates the Data structure resource state in the Requests branch, by adding the new request with it timestamp. Given the specific context in which the command to be executed is ”publish, the value ”write” is appended to the Type resource, to signify that the request pertains to a write operation.

The call_command_end event, which is matched with the initial call_command_start event based on the FD, is used by the analysis to indicate the end of the command decoding and execution. The end_read_client_query event, which is matched with the preceding start_read_client_query based on the FD, marks the end of the connection reading.

Every alteration, made to the state of a resource in the model, is reflected as a state transition in the automaton. Throughout the process of the model construction, the system undergoes several transitions. A timestamp is assigned to each state, which matches a distinct event recorded in the trace. The SHT retains a history of the sequence of system states and transitions. Hence, it is possible to ascertain the state of the system at a specified timestamp by querying the SHT.

Upon reading from the connection, Redis acknowledges the client. The tracepoint write_to_client_start is triggered whenever a message is transmitted from the server to the client. As the connection is not yet withdrawn from the context, the analysis modifies the system state to point out the beginning of the client response. The FD, obtained from the write_to_client_start event, is used to identify the SHT branch position that corresponds to the initial client connection.

Figure 4 depicts the system move to the ”Write to client” state. The algorithm uses the write_to_client_end event to signify the end of the response transmission to the client. The FD is used to match the two events. Finally, the constructed data structure is used by the state system to provide a snapshot of the system state at a specific timestamp.

The same example can be used to show how the Bus branch is populated during the analysis. The bus defines the state of network communication within a Redis cluster, and is populated by the cluster_send event, that is triggered when Redis broadcasts the publish message to the nodes on cluster. In this case, the status of the Volume resource in the SHT takes the value of the calculated volume of data sent metric. The Type resource is appended with the value of the communication type, in this case ”broadcast”.

All the branches of the SHT are populated based on event attributes. The FD is a discriminator for different ”Connections” and ”Requests” objects. The Data structure resources store all the objects for a given branch. For instance, it stores all the connections represented by the FDs, in the case of the Connections branch.

TC extensibility enables the development of extension modules that leverage the SHT as the data source for a variety of views. These extensions result in visual and interactive tools that facilitate the debugging of performance issues in Redis.

The integration process assembles various analyses to provide a comprehensive and detailed view of the system operation, facilitating performance analysis with a high level of granularity. For instance, this integration enables the visualization of interactions between different components of the microservice architecture as spans. However, it is crucial to be able to pinpoint the cause of a bottleneck when one is detected, whether due to a bug, a blocked process, or another issue. Delving deeper into a problem, at a finer granularity, is necessary to trace back to the root cause.

When a bottleneck is identified within Redis, the Redis analysis can be used to accurately determine the cause. Similarly, if the bottleneck is located within a Node.js microservice, the granular analysis of that environment can be leveraged for precise identification of the cause. The same applies to heterogeneous microservices developed with other technologies.

Integration offers a unified view of the system by observing interactions between microservices, while granular analyses of each environment enable tracing back to the root cause of a bottleneck.

In tracing components of the microservice architecture, events such as http_client_request, http_server_receive, http_server_response, and http_client_response are generated with each microservice interaction. These events capture the moments when a microservice sends a request to another, receives a request, sends back a response, and when the response is received by the sender, respectively.

The analysis relies on the attributes of these events to connect components. Attributes include source and destination addresses, source and destination port numbers, invoked services, and file descriptor numbers.

This information allows for the reconstruction and alignment of different interactions, connecting them with analyses developed for various environments, to seamlessly integrate them into a unified analysis tool.

While we used two environments (Node.js and Redis) in our case, this approach can be extended to various environments, such as Java, Golang, and others.

In this use case, to demonstrate the efficiency and advantages of our integrated performance analysis approach, the application MICROSERVICE-RESTful-Nodejs¹¹1\urlA was deployed and extended to add additional features, such as message publishing for subscribers.

The microservices application is developed in Node.js and uses Redis as a cache. It was modified to include message broker functionalities. It consists of five microservices organized as follows:

• •

  The ”user” microservice manages user-related requests within the system.

• •

  The ”user” microservice manages user-related requests within the system.

• •

  The ”Order” microservice handles different orders made by users.

• •

  The ”Gateway” microservice receives user requests and redirects them to the appropriate microservice.

• •

  The ”Redis Gateway” microservice is contacted by other microservices looking to interact with Redis. It forwards the requests to the Redis server and returns responses to the relevant microservices.

• •

  The ”MySQL Gateway” microservice is responsible for managing various requests with the MySQL database.

To enable the assembly of blocks from the two different environments (Node.js and Redis) for performing granular performance analysis, the original Redis and Node.js images were replaced with instrumented images.

In the case of Node.js, Kabamba et al. [15] proposed a low-overhead approach for transparent tracing for Node.js-based microservices. The reader is referred to their work for more details.

Running the application generates local traces in each node of the system. These traces are aggregated and loaded into TC. During the loading process, algorithms performing optimized analyses handle trace events, extract metrics from their attributes, and build a model on disk for each assembled environment.

The execution of the analyses produces two concurrent models under TC, one related to Node.js and the other to Redis. The extensions of the views generated by the various analyses allow them to be combined into a unified, integrated, and precise tool for performance analysis. The granularity is defined by each of the analyses developed for the different environments.

An overview of the outcomes of the performed analyses is presented in Figure 5. In the latter figure, the top perspective pertains to operations executed in Node.js. It can be seen how the integration analysis aligns all executions. The lower granular perspectives pertain to operations executed in Redis. Notably, these outcomes are acquired in a transparent manner, devoid of any involvement from the developers. The system deployment, tracing, and analysis are all carried out in a seamless fashion. The responsibility of the developer is to accurately determine the nature of the performance issue by using the interactive tools that are generated.

The present use case sufficiently demonstrates one of the major features of our tool, which allows tracking the life cycle of a request through a Redis infrastructure. Available monitoring and performance tracking tools primarily rely on established metrics to detect performance issues in Redis. These metrics may include disk write speed, the number of queries, memory-related information, to name a few. However, in a Redis infrastructure, such as a cluster, it may be essential to trace the execution path of a request to precisely identify where and when a request might be blocked, if necessary. This requires correlating information from all nodes in the cluster, synchronizing them using efficient analytical methods, to establish the path a request follows and visualize its journey through various nodes until the end of its life cycle.

This capability potentially allows for the precise localization of a performance issue occurring on the critical path of a request. To demonstrate this unique feature of our approach, we modified the Redis-bench client to enable it to send various types of commands, such as ”publish” and ”subscribe.” The benchmark is then executed with 20,000 requests for each command (get, set, subscribe, publish).

Figure 6 illustrates the flow of some requests processed in the Redis cluster. A performance issue can be observed, occurring during the reading of a message transmitted from one node to another. The read state is represented in the blue segment. When compared to various other requests, reading a message in the cluster takes less time.

By parallelizing the Redis Netflow view, which shows the life cycle of requests, and the Redis Data Volume view, a correlation is observed between the performance issue, and a significant increase in the volume of data leaving through the bus. See Figure 7. This directly suggests a relationship between the performance issue and the state of the queue at the network interface.

Such a view also allows visualizing the actual execution time of a command, how long the request takes on each node visited, and how much time it takes within the cluster before reaching the client.

In this use case, we demonstrate the effectiveness of our tool in detecting performance issues related to the communication within a Redis cluster. This specific case identifies a performance problem raised on GitHub by developers. This use case clearly demonstrates how our model level of abstraction, in terms of the communication bus, can be applied to conduct a performance analysis under Redis. The bug described on GitHub, which was still unresolved, pertains to the context of ”publish” requests sent to a Redis infrastructure consisting of a cluster with a Primary/Replica or Primary/Primary configuration. Initial experiments indicate, for instance, that when 10KB of data is published in a Redis cluster, subscribers indeed receive 10KB of data, but the data exchanged between the cluster nodes is ten times greater. The use of a network monitoring tool confirms that the volume of data leaving the network interface imposes a very high overhead on the cluster.

To reproduce the performance problem, a Redis cluster with $3$ nodes was configured. The microservice application ”nextjs-express-redis-microservice-architecture” was used, along with Jmeter [3], to generate users load for publishing messages to the cluster, with each client writing to a specific channel. The connection is established on Node $1$. On Node $2$, a client has subscribed to messages on the same channel, and is supposed to receive all the messages emitted by the publisher.

Figure 8 shows the result of the executed benchmark. The blue curve shows the progress of the volume of data entering the cluster over time, via the connection established by the client on Node $1$. This same volume of data is received by the client on Node 2. However, there is a drastic increase in the volume of data transmitted within the cluster bus, as indicated by the red curve.

Further investigation reveals that the overhead imposed on the data volume increases linearly with the number of nodes connected to the cluster. Two elements significantly impact the volume of data exiting the interface. First, Redis uses a specific protocol called Gossip to encode communications between the cluster nodes. The encapsulation of the data received at Node $1$ is done using Gossip, which inherently introduces a very high overhead for small-sized data. The second element affecting the volume of data exiting the interface is that the communication on the bus is performed for each ”publish” request in a broadcast manner. In other words, Node $1$ broadcasts the same message to all nodes connected to the cluster, as depicted in Figure 9.

This use case reveals a Redis performance problem inherent to the Gossip protocol it employs. Resolving this issue requires a reevaluation of its communication mechanism within the cluster.

This use case reveals a performance issue that occurs when sending a request containing a large item, in multiple parts, to Redis. The problem arises when Redis is compiled with TLS support and is run with multi-threading enabled for I/O operations.

To reproduce the performance problem, traffic is subsequently generated using Memtier[1], which supports TLS, to execute multiple concurrent requests on Redis. This results in the activation of threads to handle various I/O operations. During the benchmark execution, sending an isolated request with a large volume of data arriving in parts forces OpenSSL to have remaining bytes in the buffer. This automatically creates a performance problem that leads to a Redis crash.

Our approach accurately exposed the sequence of events that leads to this performance problem. As can be observed in Figure 10, which shows a portion of the Threads branch of the model, the view allows the visualization of the history of different established connections stored in the SHT. The numbers on the right represent file descriptors. In Redis, events arrive under different connections where they are read and processed. At the end of their processing, the events become unreadable only by being removed from the context of the connection to which they belonged. This operation is instrumented by the tracepoint delete_file_event.

However, the connection remains open and can be reused for reading various other events, unless it is explicitly closed or due to abnormal behavior in Redis execution. By carefully observing Figure 10, it can be seen that, for the connection identified by number $72$, the Operations attribute constitutes the logical resource associated, attached as per the model description. In other words, the resource is not physical but rather logical in nature in this instance. In this case, the various operations executed on this connection will be associated with the thread that performs them.

A particular thread that draws attention is the one responsible for running the event loop. As described in Section 3, the EL reads incoming events on the connection, decodes the command to be executed, and queues it for processing in its next phase. The ”Read” state indicates the event reading by the thread, while the status described as ”Registered” indicates the state of the connection handler.

Based on the foundations laid out above, a description of the unique features of our tool, in accurately pinpointing the root cause of the bug, is given.

This particular use case illustrates a Redis bug concerning the TLS support with OpenSSL. When a big item is transmitted to Redis in numerous elements, Redis optimizes its operations by exclusively requesting the data required to finish the reading. Consequently, it prevents the creation of extra copies. On occasion, this optimization strategy may results in OpenSSL buffers retaining bytes.

Redis features mechanisms for periodically determining whether pending data is present in the buffer to mark the connection as such. When the multi-threading reading option is activated, threads from the pool will execute the connection reading. Given that the connection is identified as having pending data in the buffer, the next phase of the EL will entail a thread reading the connection to retrieve the pending data. Once no further data is available for reading, the connection will no longer be identified as such. It can thus be reused in response to subsequent incoming events.

In the specific case of our experiment, the forced closure of the connection on FD $132$ triggers a new read event on the connection. Figure 11 depicts the reading of the client request by the EL. Since TLS support is enabled, the SSL handler calls the internal SSL reading function within Redis. A detailed look on Figure 11 captures the state of the thread transitioning to ”Reading SSL bytes=8192”. A straightforward deduction provides more precision regarding the amount of data that Redis requested from OpenSSL during the connection reading. In this case, $8192$ bytes are read. After the reading, the EL checks whether additional data is still pending in the buffer. If so, the connection is added to a list for processing in the ”RUNNING TASK” phase. In Figure 11, the thread reading the connection is the main Redis process that manages the EL.

As soon as the EL enters the next ”RUNNING TASK” state, the tracepoint handleClientWithPendingReadsUsingThreads is activated. This indicates the involvement of the I/O threads due to the activation of this support during Redis launch. Figure 12 depicts the second iteration of reading the connection. In this specific phase, the concerned thread traverses the list and generates read events for each of the connections with pending data in the buffer. The same connection FD $132$ is read again, as indicated by the thread status in Figure 12. This time, the EL reads $101$ bytes in this second iteration.

The check for pending data in the buffer is performed once more. In this case, the connection is again added to the list of connections with pending data for processing in the buffer. In the subsequent phase of the loop, represented by the ”RUNNING TASK” state, as shown in Figure 13, the thread once again goes through the list and generates read events on each connection present. This time, $18$ bytes are read. In the fourth iteration, Figure 14, since the quantity of data is not greater than zero, indicating that there is no more data pending in the buffer, the resources associated with the client represented by the connection are released. This can be observed in Figure 14 under the ”FREEING CLIENT” state.

The connection is then removed from the list of connections with pending data in the buffer. However, it is not removed from the list of connections requiring the activation of threads for I/O processing. With the resources of this connection now released, the FD appears as readable. In the next phase of the EL (RUNNING TASK), given that there is no more pending data in the buffer for connection FD $132$, the activation of the I/O context, allowing for thread-based processing delegation, is not triggered, as there is no more data waiting to be read.

In the next cycle of the EL, since the connection is still readable, a read event is generated. This can be observed in Figure 15. This time, a different thread comes into play and performs the reading on the connection, adding it to the list of connections requiring the activation of the thread context for I/O processing. With careful attention, this operation adds the same connection a second time to the thread I/O processing list.

The consequence is that when there is no more data pending in the buffer, the thread frees the client connection for a second time, leading to the crash of Redis. A focused view of those operations is depicted by Figure 16. In response to this unexpected behavior, the connection is automatically closed, as depicted by Figure 17, and the sequence of events results in a system crash.

This problem exposes a synchronization flaw in Redis 7. Furthermore, we extended the experiment by introducing delays in the input/output thread reading operation, using a timer to simulate contention during the execution of the thread read callback. In some cases, this led to a race condition, detected by our tool, clearly showing that, in the same context, two different threads accessed the same connection, resulting in abnormal system behavior.

The average execution time of various commands issued by the client is illustrated in Figure 18(a). Redis-benchmark was utilized to conduct the investigation. To assess the effectiveness of our solution in tracing, one million queries were sent to the server for each command on a local computer. A comparison between the execution of commands with and without tracing enabled reveals a disparity in the average execution time (see Figure 18(a)). The overhead incurred by tracing is approximately 7%.

The fixed minimum guaranteed duration for processing the tracepoint by LTTng is the cause of this. However, the investigation is conducted directly on the internal processing of Redis and not in response to a request from a network service in a microservices context. LTTng is presently considered to be the world fastest tracer and imposes a minimal amount of system overhead.

Redis interacts with modules or external applications in the network, as part of its normal execution, to provide a highly available infrastructure. The fixed overhead introduced by tracing with our approach, which is approximately 70 microseconds in a configuration of concurrent command processing issued on 100 open connections, is absorbed by the communication time of microservice infrastructures.

The resource consumption of the executed benchmark is illustrated in Figure 18(b) and Figure 18(c), corresponding to its usage with and without trace activation. It is clear that, on average, the curve does not impose a substantial burden on the system. This is due to the optimization of the instrumentation of the application, and the type of tracer employed. Comparatively to the non-traced application, the CPU consumption curve for the traced application exhibits a comparable pattern. The memory consumption curves exhibit a nearly identical profile in both scenarios, indicating that our solution has minimal effect on resource utilization.

Trace analysis is a critical component of our methodology, as it enables applying algorithms that have been designed to discover correlations among metrics derived from event attributes. It facilitates the creation of a data structure that is stored on disk and that contains the built model. This data structure is then used by the visualization tools needed for studying system performance.

In Figure 18(d), the resources consumption incurred by running the analysis is depicted. To speed up the process, TC leverages a multi-threading approach, which explains the peaks in CPU consumption. However, memory is not much affected, since the designed data structure, storing the model data, is written to the disk. Figure 18(e) presents the time it takes to perform the analysis based on the trace file size. The analysis time is the duration necessary to parse a provided trace and construct the data structure that stores the model on disk. This data structure can then be queried by implemented views, in order to display correlated information, facilitating an interactive comprehension of the operation of the system.