Per-request event detection to improve request-response latency

• US 10,579,446 B2
• Filed: 04/13/2018
• Issued: 03/03/2020
• 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
• Primary Examiner(s): Roni, Syed A
• Application Number:
  US15/952,849
• Publication Number:
  US 20190317836A1
• Time in Patent Office: 690 Days
• Field of Search: None
• 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 configured to;

receive a request, assign the request a transaction identifier, and identify 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; and

interact with a plurality of worker threads to execute the plurality of workflows, wherein each worker thread corresponds to one of the workflows and comprises;

task execution logic, in the worker thread, that activates computing subroutines in the computing system to execute the tasks in the corresponding workflow; and

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

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

a latency detection system that is external to the plurality of worker threads and comprises;

an event detector configured to detect the latency events raised by the plurality of worker threads;

time capture logic configured to capture time stamps corresponding to the detected latency events;

stack trace capture logic;

event processing logic configured to control the stack trace capture logic to capture, for each latency event, a stack trace of the runtime stack, in response to the latency event; and

data aggregation logic configured to aggregate the 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 each workflow, and wherein the event raising logic comprises:

start event generator logic configured to raise a start event when the task execution logic begins executing the tasks for a 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 5 wherein a 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 a 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 suspend event, with the first worker thread, indicative of the computing subroutines suspending execution of the tasks in the first workflow;

raising a resume event indicative of the computing subroutines resuming execution of the tasks in the first workflow;

detecting, at an event detector that is separate from the first worker thread, the suspend event and the resume event;

generating control signals to capture

a suspend timestamp based on the suspend event;

a suspend stack trace;

a resume timestamp based on the resume event; and

a 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;

controlling a 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, the resume stack trace, and the suspend time metric in the suspend-resume event record; and

aggregating the timestamps and the 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;

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;

raising an end event when the computing subroutines complete execution of the tasks in the first workflow;

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

controlling the 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 14 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.

18. A computing system, comprising:

at least one processor; and

memory storing instructions executable by the at least one processor, wherein the instructions, when executed, configure the computing system to;

assign a received request a transaction identifier and identify 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;

activate, using a first worker thread computing subroutines in the computing system to execute the tasks in a first workflow of the identified workflows;

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

raise a suspend event, with the first worker thread, indicative of the computing subroutines suspending execution of the tasks in the first workflow;

capture, in response to the suspend event, a timestamp associated with the suspend event and a stack trace of the runtime stack;

generate a suspended time metric indicative of a time that the first workflow was suspended based on the timestamp;

generate an event record including a thread identifier indicative of the first worker thread, the timestamp, the stack trace, and the suspend time metric; and

aggregate the timestamps and the 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.

19. The computing system of claim 18 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.