Incorrect LastReqTime

[cigaras]

While using SQL Anywhere 17.0.10.6175 and 17.0.11.6800 I encounter an error on a production server that connection property LastReqTime is earlier by 5 to 15 minutes. In some cases LastReqTime is even earlier than LoginTime.

select * from sa_performance_diagnostics() where LastReqTime < LoginTime

How can this be? I can not reproduce it on any of my dev environments, and have no idea where to start to search for a fix.

Update 1:

select @@version, current time, connection_property('LastReqTime')

[jack_schueler]

I assume that RequestTiming is ON. Do you have some sample rows you could share? Perhaps a stare at them might help. Other thoughts... Are some clients coming from time zones different than the server? Did this happen over a switch from standard time to daylight saving time?

[Breck_Carter]

> RequestTiming is ON

FWIW LastReqTime has been in SQL Anywhere since forever (V5 at least) and does not depend on RequestTiming like these new things (v10) do...

ReqTimeActive ReqTimeBlockContention ReqTimeBlockIO ReqTimeBlockLock ReqTimeUnscheduled

[Breck_Carter]

My guess is the underlying statistic CONNECTION_PROPERTY ( 'LastReqTime" ) is not affected by this symptom, but sa_performance_diagnostics() is built upon a hidden intern(al) procedure that may have a bug.

[cigaras]

If I execute select connection_property('LastReqTime') multiple times in rapid succession, I should get time close to current time, yet I get time 8 min. early on 17.0.11.6800 and 15 min. early on 17.0.10.6175, see attached picture in the question.

[jack_schueler]

For how long has the server been up and running. The current time value should be the actual OS local time of day. The LastReqTime is based on an internal server clock. Is the current time value correct and the LastReqTime off? Perhaps you are seeing drift in the database server's internal clock? What operating system are you running the server on?

[cigaras]

Yes, current time value is correct, LastReqTime is off. Server OS is Windows Server 2008 R2 and OS clock is showing the correct time.

DB that is off by 15 min is up since 2021-11-23, the one that is off by 8 min is up since 2022-01-19 (select property('StartTime')). Computers, running those DBs, have respective uptimes of 120 and 60 days (according to task manager).

[VolkerBarth]

Is the db server running in a virtualized environment?

FWIW, a similar issue has already been discussed with v12, see this (unanswered) question.

I could imagine that this problem might arise on our servers once again after DST has been applied and before they have been rebooted then...

[regdomaratzki]

see attached picture in the question

It may just be me, but I just see a broken link in the question, not a picture.

[regdomaratzki]

So it sounds like the database engine has been running for the same amount of time that the computer has been up and running.

I wonder if the issue is related to the time on the computer changing while the database engine is running? Are you able to run a test where you stop and start the database engine (no need to reboot the computer) to see if the problem resolves?

Thanks, Reg

[cigaras]

Restarting the DB service did resolve the issue, however it would be great if it would not repeat itself 🙂

[cigaras]

Yes, DB server is running in a virtualized environment.

Shouldn't DST change push clock by an hour, not by some arbitrary amount?

Restarting the DB service did resolve the issue, however it would be great if it would not repeat itself 🙂

[VolkerBarth]

I surely agree that the time sources for the current server time and for "request time" should stay consistent over time (pun intended), and of course even across a DST change. (Though for expected ever-increasing and non-unique values like a DEFAULT TIMESTAMP, a DST change to the previous hour is of course difficult to achieve...)

But according to that older question, the impression remains that both kind of times do have different time sources that can fall apart.

And now I hope SQL Anywhere engineers will clarify this issue. 🙂

[chris_keating]

I recall Docker VMs having an issue where the clock would drift that would affect applications like SQLA that queried the system time. What virtualization environment are you running?

[VolkerBarth]

But even if the system time within a VM would loose precision over time compared to the host's system clock, that does not explain why SQL Anywhere would display different values for the current time and a "LastReqTime" of a currently started request, as in the OP's sample...

[cigaras]

Environment is managed by our client, so I am not sure, but I doubt Docker is involved. According to msinfo32 system manufacturer is VMware, Inc, and after some Google I found a lot of info on VMware time drifting, including a huge document by VMware themselves https://www.vmware.com/content/dam/digitalmarketing/vmware/en/pdf/techpaper/Timekeeping-In-VirtualMa... Still, as already said by Volker Barth, SA should not count time differently.

[cigaras]

Any advice on best way to contact SA engineers?

[Breck_Carter]

JBSchueler said this in an earlier comment... "The current time value should be the actual OS local time of day. The LastReqTime is based on an internal server clock."

[VolkerBarth]

Well, they do already read and discuss here, namely Jack Schueler, Chris Keating and Reg Domaratzki... 🙂

[chris_keating]

I have run a test that invokes the sa_performance_diagnostics() query cited at the start of the thread 500K times and cannot reproduce the behavior. And I often recommend using that procedure in an event to collect info to troubleshoot performance issues. To date, I have never seen a case where the values have drifted as shown here. You perhaps can open a support case and/or provide to this thread info about the virtualized environment (i.e., Hyper-V, VMWare), the virtualized OS and host (what OS is hosting the VM),has the VM ever been suspended and then reactivated - providing as much detail may help to recreate an environment that encounters the behavior.