PER-REQUEST EVENT DETECTION TO IMPROVE REQUEST-RESPONSE LATENCY

• US 20190317836A1
• Filed: 04/13/2018
• Published: 10/17/2019
• Est. Priority Date: 04/13/2018
• Status: Active Grant

• Current Assignee: Microsoft Technology Licensing LLC (Microsoft Corporation)
• Original Assignee: Microsoft Technology Licensing LLC (Microsoft Corporation)
• Inventors: Kuzior, Matthew Christopher, Dangayach, Harsh Satyanarayan, Wilkins, Alexander Lawrence, Smith, Matthew John
• Granted Patent: US 10,579,446 B2
• Time in Patent Office: Days
• CPC Class Codes: G06F 9/485 Task life-cycle, e.g. stopping, restarting, resuming execution G06F9/4881 takes precedence
• CPC Class Codes: G06F 9/542 Event management; Broadcasting; Multicasting; Notifications
• CPC Class Codes: H04L 67/01 Protocols
• CPC Class Codes: H04L 67/10 in which an application is distributed across nodes in the network software deployment G06F8/60; multiprogramming arrangements G06F9/46
• CPC Class Codes: H04L 67/62 Establishing a time schedule for servicing the requests

Abstract

Events are raised by a worker thread that is executing a workflow, when the worker thread starts, suspends, resumes and ends execution of the workflow. A latency detection system, that is external to the worker thread, detects when these events are raised and logs a timestamp and a stack trace, corresponding to the workflow and the event that was raised.

Claims

1. A computing system, comprising:

request receiving logic that receives a request, assigns the request a transaction identifier and identifies a plurality of workflows corresponding to the request, each workflow having a set of tasks to be executed to generate a response to the request;

task execution logic, in a first worker thread, that activates computing subroutines in the computing system to execute the tasks in a first workflow of the identified workflows;

a memory that stores a runtime stack indicative of the computing subroutines of the computing system that are active;

event raising logic that raises a latency event when a latency operation is performed by the task execution logic in executing the tasks in the first workflow;

time capture logic that captures a time stamp;

stack trace capture logic that captures a stack trace of the runtime stack;

event processing logic, external to the first worker thread, that detects the latency event and generates control signals to control the time capture logic to capture a timestamp and to control the stack trace capture logic to capture a stack trace of the runtime stack, in response to the latency event; and

data aggregation logic that aggregates captured timestamps and captured stack traces across the plurality of different workflows corresponding to the request, based on the transaction identifier.

2. The computing system of claim 1 wherein the data aggregation logic is configured to identify an end-to-end latency indicative of a time to respond to the request, based on the aggregated timestamps.

3. The computing system of claim 1 wherein the event processing logic comprises:

metadata capture logic configured to capture metadata based on the detected latency event, the data aggregation logic aggregating the metadata across the plurality of different workflows.

4. The computing system of claim 1 wherein the request receiving logic is configured to receive a plurality of different requests, of different request types, and wherein the data aggregation logic is configured to aggregate the captured timestamps and the captured stack traces across the plurality of different requests based on the request types.

5. The computing system of claim 1 wherein the worker thread comprises workflow identifier generator logic configured to assign a workflow identifier to the first workflow, and wherein the event raising logic comprises:

start event generator logic that raises a start event when the task execution logic begins executing the tasks for the first workflow, the start event including the workflow identifier assigned to the first workflow.

6. The computing system of claim 5 wherein the event processing logic comprises:

start logic configured to store a workflow-thread association between the first workflow and the worker thread that raised the start event based on the workflow identifier assigned to the first workflow.

7. The computing system of claim 4 wherein the first worker thread includes update logic configured to raise an update event indicative of a change in the workflow identifier assigned to the first workflow to an updated workflow identifier and wherein the event processing logic comprises:

update logic configured to determine whether the first worker thread is associated with the start event, and if so, modify the workflow-thread association based on the updated workflow identifier.

8. The computing system of claim 1 wherein the first worker thread includes suspension logic configured to raise a suspend event indicative of the task execution logic suspending execution of the tasks in the first workflow and wherein the event processing logic comprises:

suspend logic configured to control the time capture logic to capture a timestamp indicative of when the task execution logic suspended execution of the tasks in the first workflow and generate a suspension event record including a thread identifier indicative of the first worker thread and the timestamp.

9. The computing system of claim 8 wherein the suspension logic is configured to raise the suspend event to include an indication of whether the first workflow can be resumed on a different worker thread, different from the first worker thread.

10. The computing system of claim 9 wherein the first worker thread includes resumption logic configured to raise a resume event indicative of the task execution logic resuming execution of the tasks in the first workflow and wherein the event processing logic comprises:

resume logic configured to control the time capture logic to capture a timestamp indicative of when the task execution logic resumed execution of the tasks in the first workflow and to control the stack trace capture logic to capture a stack trace and to generate a resumption event record including the timestamp and the stack trace.

11. The computing system of claim 10 wherein, if the suspend event included the indication that the first workflow can be resumed on a different worker thread, different from the first worker thread, then the resume logic is configured to capture the workflow identifier assigned to the first workflow, from the resume event, and to modify the workflow-thread association to indicate that the different thread, that raised the resume event, is associated with the first workflow.

12. The computing system of claim 11 wherein the resume logic is configured to generate a suspended time metric indicative of a time that the first workflow was suspended based on the timestamp that indicates when the task execution logic suspended execution of the tasks in the first workflow and the timestamp that indicates when the task execution logic resumed execution of the tasks in the first workflow, and to include the suspend time metric in the resumption event record.

13. The computing system of claim 12 wherein the first worker thread includes end event generator logic configured to raise an end event indicative of the task execution logic completing execution of the tasks in the first workflow and wherein the event processing logic comprises:

end logic configured to control the time capture logic to capture a timestamp indicative of when the task execution logic completed execution of the tasks in the first workflow and to control the stack trace capture logic to capture a stack trace and to generate an end event record including the timestamp and the stack trace.

14. A computer implemented method, comprising:

receiving a service request;

assigning the service request a transaction identifier;

identifying a plurality of workflows corresponding to the request, each workflow having a set of tasks to be executed to generate a response to the request;

activating, with a first worker thread, computing subroutines to execute the tasks in a first workflow of the identified workflows;

maintaining a runtime stack indicative of the computing subroutines that are active;

raising a latency event, with the first worker thread, when a latency operation is performed in executing the tasks in the first workflow;

detecting the latency event at an event detector that is separate from the first worker thread;

generating control signals to capture a timestamp and to capture a stack trace of the runtime stack, in response to the latency event; and

aggregating captured timestamps and captured stack traces across the plurality of different workflows corresponding to the request, based on the transaction identifier to identify an end-to-end latency indicative of a time to respond to the request, based on the aggregated timestamps.

15. The computer implemented method of claim 14 wherein receiving a service request comprises:

receiving a plurality of different requests, of different request types, and wherein aggregating includes aggregating the captured timestamps and the captured stack traces across the plurality of different requests based on the request types.

16. The computer implemented method of claim 14 and further comprising assigning a workflow identifier to the first workflow, and wherein raising a latency event comprises raising a start event when the computing subroutines begin executing the tasks for the first workflow, the start event including the workflow identifier assigned to the first workflow, and raising an end event when the computing subroutines complete execution of the tasks in the first workflow and wherein generating control signals comprises:

controlling time capture logic to capture a start timestamp based on the start event;

controlling a data store to store a workflow-thread association between the first workflow and the worker thread that raised the start event based on the workflow identifier assigned to the first workflow;

controlling the time capture logic to capture an end timestamp based on the end event; and

controlling stack trace capture logic to capture an end stack trace, based on the end event.

17. The computer implemented method of claim 16 wherein raising a latency event comprises raising a suspend event indicative of the computing subroutines suspending execution of the tasks in the first workflow, and raising a resume event indicative of the computing subroutines resuming execution of the tasks in the first workflow and wherein generating control signals comprises:

controlling the time capture logic to capture a suspend timestamp based on the suspend event;

controlling the stack trace capture logic to capture a suspend stack trace;

controlling the time capture logic to capture a resume timestamp based on the resume event;

controlling the stack trace capture logic to capture a resume stack trace;

controlling the data store to generate a suspend-resume event record including a thread identifier indicative of the first worker thread, the suspend timestamp, the suspend stack trace, the resume timestamp and the resume stack trace;

generating a suspended time metric indicative of a time that the first workflow was suspended based on the suspend timestamp and the resume timestamp; and

controlling the data store to include the suspend time metric in the suspend-resume event record.

18. The computer implemented method of claim 17 wherein raising the suspend event includes providing an indication of whether the first workflow can be resumed on a different worker thread, different from the first worker thread, and if the suspend event included the indication that the first workflow can be resumed on a different worker thread, different from the first worker thread, then generating control signals comprises:

identifying the workflow identifier assigned to the first workflow, from the resume event; and

controlling the data store to modify the workflow-thread association to indicate that the different thread, that raised the resume event, is associated with the first workflow.

19. A computing system, comprising:

request receiving logic that receives a request, assigns the request a transaction identifier and identifies a plurality of workflows corresponding to the request, each workflow having a set of tasks to be executed to generate a response to the request;

task execution logic, in a first worker thread, that activates computing subroutines in the computing system to execute the tasks in a first workflow of the identified workflows;

a memory that stores a runtime stack indicative of the computing subroutines of the computing system that are active;

event raising logic that raises a latency event when a latency operation is performed by the task execution logic in executing the tasks in the first workflow;

time capture logic that captures a time stamp;

stack trace capture logic that captures a stack trace of the runtime stack;

event processing logic, external to the first worker thread, that detects the latency event and generates control signals to control the time capture logic to capture a timestamp and to control the stack trace capture logic to capture a stack trace of the runtime stack, in response to the latency event; and

data aggregation logic that aggregates captured timestamps and captured stack traces across the plurality of different workflows corresponding to the request, based on the transaction identifier and to identify an end-to-end latency indicative of a time to respond to the request, based on the aggregated timestamps.

20. The computing system of claim 19 wherein the request receiving logic is configured to receive a plurality of different requests, of different request types, and wherein the data aggregation logic is configured to aggregate the captured timestamps and the stack captured traces across the plurality of different requests based on the request types.