dynatrace-extensions / dt-extensions-python-sdk

Dynatrace Python Extensions SDK
https://dynatrace-extensions.github.io/dt-extensions-python-sdk/
MIT License
8 stars 2 forks source link

Each time it is run, the execution start time is delayed by a few milliseconds, so occasionally a one-minute data point is missed. #69

Closed gomachssm closed 1 month ago

gomachssm commented 1 month ago

Describe the bug The default execution interval is 60 seconds, but in reality it is around 60.0x seconds. Therefore, if data collection starts at 00:00:59.995, the next data collection start time will be 00:02:00.012, and data for 00:01 will not be collected, resulting in missing data when checking metrics in Data Explorer. Please check this URL as it is the question I asked in the community. https://community.dynatrace.com/t5/Extensions/The-execution-time-of-Extension-2-0-created-with-Python-is-a/m-p/248619

To Reproduce Steps to reproduce the behavior:

  1. Create an extension for OneAgent using the SDK.
  2. Monitor any host with the extension.
  3. If you wait a few hours or days, you will miss 1 minute of metrics.

Expected behavior 1-minute metrics should not be missing no matter how many days it is run in a row. The time when the query function is called should not be delayed no matter how many days have passed. I don't think it's necessary for the difference from the previous time to be 0.000 seconds, but I don't think it's acceptable for it to be delayed by 1 to 30 milliseconds each time, as is the case now.

Screenshots When I looked at the log, there was no start log at 17:54, and when I looked at DataExplorer, the data at 17:55 was missing.

2024-06-21 17:50:59,902 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 17:51:59,926 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 17:52:59,956 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 17:53:59,985 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 17:55:00,015 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 17:56:00,023 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 17:57:00,053 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 17:58:00,081 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 17:59:00,111 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.
2024-06-21 18:00:00,121 [INFO] dynatra ... utor-0_0): query START mysmp2:0.0.6.

image

Additional context

Looking at the source code, it seemed that the cause of this problem was the use of scheduler.enter. For example, I thought that using scheduler.enterabs would prevent millisecond errors from accumulating.

dlopes7 commented 1 month ago

Thanks for reporting, I'm pushing a change where we won't use sched.enter anymore, instead we will use sched.enterabs

This will resolve the issue with the slow time drift. There will still be variation (milliseconds up or down) for each execution, but they won't accumulate anymore, and since we don't sechedule at 0 second of the minute, it won't be enough to "jump" to a different minute.

dlopes7 commented 1 month ago

Example:

before:

2024-06-22 17:59:01,805 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start - baseline
2024-06-22 17:59:02,806 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +1ms
2024-06-22 17:59:03,812 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +7ms
2024-06-22 17:59:04,821 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +16ms
2024-06-22 17:59:05,835 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +30ms
2024-06-22 17:59:06,846 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +41ms
2024-06-22 17:59:07,855 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +50ms
2024-06-22 17:59:08,865 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +60ms
2024-06-22 17:59:09,876 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +71ms
2024-06-22 17:59:10,888 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +83ms
2024-06-22 17:59:11,898 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +93ms
2024-06-22 17:59:12,905 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +100ms
2024-06-22 17:59:13,912 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +107ms
2024-06-22 17:59:14,921 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +116ms
2024-06-22 17:59:15,932 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +127ms
2024-06-22 17:59:16,941 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +136ms

after:

2024-06-22 17:49:33,754 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start - baseline
2024-06-22 17:49:34,762 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +8ms
2024-06-22 17:49:35,754 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +0ms
2024-06-22 17:49:36,758 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +4ms
2024-06-22 17:49:37,762 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +8ms
2024-06-22 17:49:38,757 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +3ms
2024-06-22 17:49:39,762 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +8ms
2024-06-22 17:49:40,754 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +0ms
2024-06-22 17:49:41,761 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +7ms
2024-06-22 17:49:42,751 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start -3ms
2024-06-22 17:49:43,755 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +1ms
2024-06-22 17:49:44,750 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start -4ms
2024-06-22 17:49:45,755 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +1ms
2024-06-22 17:49:46,761 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_1): method monitor start +7ms
2024-06-22 17:49:47,755 [INFO] dynatrace_extension.sdk.extension (ThreadPoolExecutor-0_0): method monitor start +1ms
dlopes7 commented 1 month ago

Please update to 1.2.3 which fixes the timedrift

gomachssm commented 1 month ago

The expected behavior has been achieved in 1.2.3. Thank you for your quick response.