search

marcingminski / sqlwatch

SQL Server Performance Monitor
https://docs.sqlwatch.io
Other
435 stars 171 forks source link

Grafana need Time in UTC instead of Local Time ([event_time] or [report_time]) #242

Closed steffenengelhamburg closed 3 years ago

steffenengelhamburg commented 3 years ago

Bug Description Grafana need all Data for [time] column in UTC.

Read https://community.grafana.com/t/microsoft-sql-server-utc-to-localtimezone/6965/18 This is a brief description of this Grafana Feature with a solution to it.

If you select data in local time like with [time] = [event_time] or [time] = [report_time] than grafana expect this columns are utc and will show dashboards with the offset. Grafana uses in our environment the Browser time (UTC+2h) to calculate the Offset of [time] column.

To Reproduce Steps to reproduce the behavior, i use UTC+2 -> German local Time

  1. Set your SQL Server & DWH to Timezone other than UTC
  2. Set your Grafana Server to same Timezone
  3. Set your Grafana Client to same Timezone

Wait some time to collect data.

This are the SQL Statements and Outputs -- Grafana need all Time in UTC instead of local Time: -- based on https://community.grafana.com/t/microsoft-sql-server-utc-to-localtimezone/6965/18 -- post from clugoimx 05/01/18

SELECT [time]= d.event_time, [Long queries] = count(distinct d.session_id)
  FROM dbo.sqlwatch_logger_snapshot_header h
    inner join [dbo].[sqlwatch_logger_xes_long_queries] d
        on  h.snapshot_time = d.[snapshot_time]
        and h.snapshot_type_id = d.snapshot_type_id
        and h.sql_instance = d.sql_instance
  WHERE h.snapshot_type_id = 7
     AND h.[sql_instance] = 'mySQL'
   AND d.event_time BETWEEN '2021-04-06T08:02:37Z' AND '2021-04-06T11:12:37Z'
   GROUP BY d.event_time
ORDER BY
  d.event_time DESC

Result is in Local time (UTC+2h) Current Local Time: 10:15 Grafana uses this as UTC Time --> Graph shows this as 12:14:15.717 instead of 10:14:15.717 time Long queries 2021-04-06 10:14:15.717 1 2021-04-06 10:13:16.380 1 2021-04-06 10:12:15.237 1 2021-04-06 10:11:23.310 1

Image shows Default Grafana Setting for non UTC Client image

Image shows SQLWatch [time]= d.event_time with wrong Offset image

Expected behavior Normal behavior: For all other Data in Grafana like Windows Counter we deliver Data in UTC. Grafana shows Time in correct local Time with Browser

DECLARE @utcoffset integer;
set @utcoffset = datediff(hh,getdate(),getutcdate());
SELECT @utcoffset AS [utcoffset]

utcoffset -2

DECLARE @utcoffset integer;
set @utcoffset = datediff(hh,getdate(),getutcdate());
SELECT [time]= dateadd(hh,@utcoffset,d.event_time)
, [Long queries] = count(distinct d.session_id)
  FROM dbo.sqlwatch_logger_snapshot_header h
    inner join [dbo].[sqlwatch_logger_xes_long_queries] d
        on  h.snapshot_time = d.[snapshot_time]
        and h.snapshot_type_id = d.snapshot_type_id
        and h.sql_instance = d.sql_instance
  WHERE h.snapshot_type_id = 7
     AND h.[sql_instance] = 'mySQL'
   AND d.event_time BETWEEN '2021-04-06T08:02:37Z' AND '2021-04-06T11:12:37Z'
   GROUP BY d.event_time
ORDER BY
  d.event_time DESC

time Long queries 2021-04-06 08:14:15.717 1 2021-04-06 08:13:16.380 1 2021-04-06 08:12:15.237 1 2021-04-06 08:11:23.310 1

Image shows Correct [time] image

The Grafana Statement is

DECLARE @utcoffset integer;
set @utcoffset = datediff(hh,getdate(),getutcdate());

SELECT [time]= dateadd(hh,@utcoffset,d.event_time), [Long queries] = count(distinct d.session_id)
  FROM dbo.sqlwatch_logger_snapshot_header h
    inner join [dbo].[sqlwatch_logger_xes_long_queries] d
        on  h.snapshot_time = d.[snapshot_time]
        and h.snapshot_type_id = d.snapshot_type_id
        and h.sql_instance = d.sql_instance
  WHERE h.snapshot_type_id = 7
     AND h.[sql_instance] = '$sql_instance'
   AND $__timeFilter(d.snapshot_time)
   GROUP BY d.event_time
ORDER BY
  d.event_time desc

I still have a Problem with my workaround in Line AND $__timeFilter(d.snapshot_time)

Because the correct statement need to be AND $__timeFilter(dateadd(hh,@utcoffset,d.event_time)) but this gives an error, instead i use for now d.snapshot_time image

Windows Server:

SQL Server:

SQLWATCH version (from DACPAC or from sysinstances)

Grafana Version

steffenengelhamburg commented 3 years ago

Hi Marcin, this "Bug" is related to all Grafana Dashboards. Currently i rewrite all of them to use [time]= dateadd(hh,@utcoffset,d.event_time) or [time]= dateadd(hh,@utcoffset,d.report_time)

When i'm ready i could send a Pull Request if you want.

Greetings from Hamburg Steffen

marcingminski commented 3 years ago

That's right, Grafana does operate on UTC times only but all the time fed from SQLWATCH should be in UTC already. The snapshot_time is in UTC. The event_time comes from the Extended Event session and should also be in UTC - that's how SQL Server logs it. When you then browse XES in SSMS it offsets the event time to your local time. SQLWATCH provides local time in the report_time column but that is not used across Grafana due to the above. Also, the report_time is also rounded up to the nearest minute as it was for the PBI dashboard.

What you are describing suggests that the event_time field is incorrect rather than the dashboard. I can see in your example you have removed aggregation. If you apply that across all graphs you will create lots of load on the SQL and Grafana which is not a good thing.

If your server is in the same timezone as your Grafana dashboard, you can set Grafana time to Browser Time but leave all the queries in UTC. It will then offset it and show charts in your local time. The problem then starts if you have multiple servers in different time zones, there's no easy fix for that.

If you change your Grafana Dashboard to Browser Time, in the settings the $__timefilter(snapshot_time) will also work as the dashboard will calculate offset based on your browser time. image

marcingminski commented 3 years ago

In [dbo].[usp_sqlwatch_logger_xes_long_queries], I found that the event_time is actually converted to local time 

[event_time]=dateadd(minute,@utc_offset_minute,xed.event_data.value('(@timestamp)[1]', 'datetime'))

but this does not happen in any other XES logger. I will have to browse past commits to understand why this was done.

marcingminski commented 3 years ago

https://github.com/marcingminski/sqlwatch/issues/244

steffenengelhamburg commented 3 years ago

Hi Marcin, thank you for your fast reply.

reg. Aggregation: You are absolutely correct. But: It's the last copy of your "Long Queries.json" Dashboard, i downloaded today. The aggregation was not used there ;)

reg. event_time: Yes i checked this twice: with a query from Grafana and on the SSMS on SQL Server. For "Long Queries.json" and Dashboard "SQL Instance Overview.json" the Line 2644 "rawSql": "SELECT \n [time]= event_time\n.... "

The Event_time is in Local Time instead of UTC. I think too it's a bug. I have a open SMC SR with our Microsoft Gold Support opened regarding this XES. I'll update you...

But maybee it's better solution to use the snapshot time for all Graphs and the event_time only for all Detailed Views until the Problem is solved.

marcingminski commented 3 years ago

Well its a bug but in SQLWATCH not in SQL Server. See https://github.com/marcingminski/sqlwatch/issues/244

marcingminski commented 3 years ago

See if this fix works for you https://github.com/marcingminski/sqlwatch/commit/68cf5a8887df1083a621d4445dafc59c006b994a

steffenengelhamburg commented 3 years ago

Hi Marcin, locks good!

If used on vw_sqlwatch_report_fact_xes_wait_events the "SQL Instance Overview.json" Line 2644 shows everything fine.

ALTER VIEW [dbo].[vw_sqlwatch_report_fact_xes_wait_events] with schemabinding
as
select [event_time]=dateadd(minute,-[dbo].[ufn_sqlwatch_get_server_utc_offset]('MINUTE'),e.event_time)

...

So One more step left on Long Queries.json: 68cf5a8 is for vw_sqlwatch_report_fact_xes_long_queries: The Select of this changed view get the correct UTC Time for event_time.

Because Grafana "Long Queries.json" don't use [dbo].[sqlwatch_logger_xes_long_queries]: We have to change the json of the Dashboard to query the view [dbo].[vw_sqlwatch_report_fact_xes_long_queries] instead of [dbo].[sqlwatch_logger_xes_long_queries]

see my last Comment with all changes

Greetings from Hamburg Steffen

steffenengelhamburg commented 3 years ago

started changing the Long Queries.json to use [dbo].[vw_sqlwatch_report_fact_xes_long_queries] now i found a missing column [long_query_id] in view [dbo].[vw_sqlwatch_report_fact_xes_long_queries] - you need this to get the query text in Long Queries.json

After all the Long Queries.json is al right! No bugs on Servers in Local time Germany with UTC+2 or Servers in UTC Time!!

Steps to do: 1) ALTER VIEW [dbo].[vw_sqlwatch_report_fact_xes_long_queries] add Column [long_query_id]

on "Long Queries.json" Line 98: "rawSql": "SELECT [time]= [event_time], [Long queries] = count(distinct [session_id])\n FROM [dbo].[vw_sqlwatch_report_fact_xes_long_queries] h\n WHERE [snapshot_type_id] = 7\n AND [sql_instance] = '$sql_instance'\n AND $__timeFilter([event_time])\n GROUP BY [event_time]\nORDER BY\n [event_time] desc",

Line 261: "rawSql": "SELECT *\n FROM [dbo].[vw_sqlwatch_report_fact_xes_long_queries]\n WHERE snapshot_type_id = 7\n AND [sql_instance] = '$sql_instance'\n AND $__timeFilter(event_time)\nORDER BY\n event_time desc",

Line 351 "rawSql": "SELECT time=getdate(), sql_text, statement\n FROM [dbo].[vw_sqlwatch_report_fact_xes_long_queries]\n WHERE snapshot_type_id = 7\n AND [sql_instance] = '$sql_instance'\n AND long_query_id = isnull('$LongQueryId',-1)\n",

Next Grafana Json: SQL Instance Overview.json Line 3376 "rawSql": "SELECT [time]= [event_time], [Long queries] = count(distinct [session_id])\n FROM [dbo].[vw_sqlwatch_report_fact_xes_long_queries]\n WHERE [snapshot_type_id] = 7\n AND [sql_instance] = '$sql_instance'\n AND $__timeFilter([event_time])\n GROUP BY [event_time]\nORDER BY\n [event_time] desc",

marcingminski commented 3 years ago

see if dashboards in the latest commit above are any better. You can get a copy there: https://github.com/marcingminski/sqlwatch/tree/3.x/SqlWatch.Dashboard/Grafana

steffenengelhamburg commented 3 years ago

Hi Marcin, great work, the issues seems to be solved.

Greeting from Hamburg Steffen