11:16 p.m.
Found some excerpts in the knowledge base article. Following excerpts from the KB article
explain why the out of order timestamp is a possibility,
"Virtual machines share their underlying hardware with the host operating system, or
on VMware ESX®, the VMkernel. Other applications and other virtual machines might also be
running on the same host machine. At the moment that a virtual machine should generate a
virtual timer interrupt, it might not actually be running. In fact, the virtual machine
might not get a chance to run again until it has accumulated a backlog of many timer
interrupts. In addition, even a running virtual machine can sometimes be late in
delivering virtual timer interrupts. The virtual machine checks for pending virtual timer
interrupts only at certain points, such as when the underlying hardware receives a
physical timer interrupt. Many host operating systems do not provide a way for the virtual
machine to request a physical timer interrupt at a precisely specified time.
Because the guest operating system keeps time by counting interrupts, time as measured by
the guest operating system falls behind real time whenever there is a timer interrupt
backlog."
Thanks,
Sriram
On 5/24/19, 11:36 PM, "Sriram Patil" <sriramp(a)vmware.com> wrote:
Ohh okay. I agree that this is very unusual behavior in a normal case because ganesha
calls time every time when logging. Also, it opens and closes file for every log
message.
I will investigate further on similar lines. Thanks for the help.
- Sriram
On 5/24/19, 9:04 PM, "Daniel Gryniewicz" <dang(a)redhat.com> wrote:
My guess is that something related to waking up the thread triggers a
system clock update from the VM host to the VM, but that this is done
asynchronously, and that it takes some time. This means that the first
call to time() in the thread is likely to get an out-of-date timestamp.
I don't know that this is the case; but VMWare, in particular, has some
really strange operation with-respect-to the system clock inside a VM.
When I last looked at this (~10 years ago, admittedly), there were some
settings you could change that would make it better, but we couldn't get
good, accurate time inside a VM no matter what we did. Note that we
needed sub-second accuracy, so you can likely make it good enough for
Ganesha timestamps.
Note: I'm blaming virtualization (and VMWare in particular) here, but I
don't know that this is the problem; I've just never seen this issue in
Ganesha before, and I have seen clock issues in VMs, so it's my best
guess. It may turn out to be something else entirely.
Daniel
On 5/24/19 10:59 AM, Sriram Patil wrote:
Hi Daniel,
Yes I have set a date format and I was running ganesha inside a container on a VMWare
VM.
But I fail to understand how come the time is different only for the first log message of
every request?
Thanks,
Sriram
On 5/24/19, 6:53 PM, "Daniel Gryniewicz" <dang(a)redhat.com> wrote:
I'm not aware of any issues, nor has anything changed in 3 years. It's
clear to me from your logs that you've set time_format and/or
date_format, but likely haven't set it to "syslog_usec", right?
This
means it's just calling time() to get the datestamp, and it's doing it
during each log message. (If you set "syslog_usec" it calls
gettimeofday())
This means, to me, that the first time a thread calls time() in a while,
it's getting back an older timestamp, but that something kicks the
timestamp back to normal after that.
I haven't seen anything like this before; time can drift, especially in
virtual machines (which is why CLOCK_MONOTONIC exists), but this doesn't
seem to be that.
Are you running in a virtual machine? If so, which type (ie, vmware,
kvm, etc.)
Daniel
On 5/24/19 1:02 AM, Sriram Patil wrote:
> CCing Frank and Daniel because I don’t see the email on the mailing list.
>
> - Sriram
>
> *From: *Sriram Patil <sriramp(a)vmware.com>
> *Date: *Friday, May 24, 2019 at 1:00 AM
> *To: *"devel(a)lists.nfs-ganesha.org"
<devel(a)lists.nfs-ganesha.org>
> *Subject: *Seeing out of order logs
>
> Hi,
>
> I am observing a weird out of order logs. As seen from the logs below,
> for threads svc_5, svc_7 and svc_14, only the first log messages appears
> with a timestamp which is about 2 minutes old. When those threads are
> actually processing the compound operations, the timestamp seems fine.
> In fact the timestamps for for the reaper thread after svc_5 are also
> out of order. I am using v2.7.2. Is there any known scenario when we can
> get these out of order logs?
>
> The following log is continuous, I have added blanks lines in between so
> that they are a bit easier to read.
>
> 2019-05-22T20:19:02Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[none] [svc_5] 1332 :nfs_rpc_decode_request :DISP
> :0x7fa674000a90 fd 21 context 0x7fa670001ac0
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_5] 839
> :nfs_rpc_process_request :DISP :Request from ::ffff:10.192.78.96 for
> Program 100003, Version 4, Function 1 has xid=3831317466
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_5] 687 :nfs4_Compound :NFS4
> :COMPOUND: There are 3 operations, res = 0x7fa670001f70, tag = NO TAG
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_5] 798 :nfs4_Compound :NFS4
> :Request 0: opcode 53 is OP_SEQUENCE
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_5] 81 :nfs4_op_sequence
> :SESSIONS :SEQUENCE session=0x7fa670049dd0
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_5] 93 :nfs4_op_sequence
> :SESSIONS :SESSIONS: DEBUG: SEQUENCE returning status NFS4ERR_EXPIRED
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_5] 977 :nfs4_Compound :NFS4
> :Status of OP_SEQUENCE in position 0 = NFS4ERR_EXPIRED, op response size
> is 4 total response size is 40
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_5] 1107 :nfs4_Compound :NFS4
> :End status = NFS4ERR_EXPIRED lastindex = 0
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[none] [svc_5] 1381 :nfs_rpc_decode_request :DISP
> :SVC_DECODE on 0x7fa674000a90 fd 21 (::ffff:10.192.78.96:1013)
> xid=3831317466 returned XPRT_IDLE
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[none] [svc_5] 1294 :free_nfs_request :DISP
> :free_nfs_request: 0x7fa674000a90 fd 21 xp_refcnt 6 rq_refcnt 0
>
> 2019-05-22T20:19:08Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[none] [reaper] 219 :reaper_run :CLIENT ID :Now checking
> NFS4 clients for expiration2019-05-22T20:21:01Z : epoch 5ce5ab1d :
> localhost : ganesha.nfsd-38[none] [reaper] 906 :nfs_client_id_expire
> :CLIENT ID :Expiring {0x7fa664004c10 ClientID={Epoch=0x5ce5ab1d
> Counter=0x00000003} CONFIRMED Client={0x7fa6700019d0 name=(27:Linux
> NFSv4.1 h10-192-78-96) refcount=2} t_delta=124 reservations=0 refcount=3}
>
> 2019-05-22T20:19:16Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[none] [svc_7] 1332 :nfs_rpc_decode_request :DISP
> :0x7fa664000b20 fd 31 context 0x7fa6680082e0 <--- XXX
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.73.159] [svc_7] 839
> :nfs_rpc_process_request :DISP :Request from ::ffff:10.192.73.159 for
> Program 100003, Version 4, Function 1 has xid=1048477897
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.73.159] [svc_7] 687 :nfs4_Compound :NFS4
> :COMPOUND: There are 1 operations, res = 0x7fa668008da0, tag = NO TAG
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.73.159] [svc_7] 798 :nfs4_Compound :NFS4
> :Request 0: opcode 53 is OP_SEQUENCE
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.73.159] [svc_7] 81 :nfs4_op_sequence
> :SESSIONS :SEQUENCE session=0x7fa664001ca0
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.73.159] [svc_7] 977 :nfs4_Compound :NFS4
> :Status of OP_SEQUENCE in position 0 = NFS4_OK, op response size is 40
> total response size is 76
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[none] [svc_7] 1381 :nfs_rpc_decode_request :DISP
> :SVC_DECODE on 0x7fa664000b20 fd 31 (::ffff:10.192.73.159:908)
> xid=1048477897 returned XPRT_IDLE
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[none] [svc_7] 1294 :free_nfs_request :DISP
> :free_nfs_request: 0x7fa664000b20 fd 31 xp_refcnt 11 rq_refcnt 0
>
> 2019-05-22T20:19:17Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[none] [svc_14] 1332 :nfs_rpc_decode_request :DISP
> :0x7fa674000a90 fd 21 context 0x7fa64403a150 <--- XXX
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_14] 839
> :nfs_rpc_process_request :DISP :Request from ::ffff:10.192.78.96 for
> Program 100003, Version 4, Function 1 has xid=3848094682
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_14] 687 :nfs4_Compound :NFS4
> :COMPOUND: There are 1 operations, res = 0x7fa64403ab90, tag = NO TAG
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_14] 798 :nfs4_Compound :NFS4
> :Request 0: opcode 53 is OP_SEQUENCE
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_14] 74 :nfs4_op_sequence
> :SESSIONS :SESSIONS: DEBUG: SEQUENCE returning status NFS4ERR_BADSESSION
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_14] 977 :nfs4_Compound :NFS4
> :Status of OP_SEQUENCE in position 0 = NFS4ERR_BADSESSION, op response
> size is 4 total response size is 40
>
> 2019-05-22T20:21:01Z : epoch 5ce5ab1d : localhost :
> ganesha.nfsd-38[::ffff:10.192.78.96] [svc_14] 1107 :nfs4_Compound :NFS4
> :End status = NFS4ERR_BADSESSION lastindex = 0
>
> Thanks,
>
> Sriram
>
_______________________________________________
Devel mailing list -- devel(a)lists.nfs-ganesha.org
To unsubscribe send an email to devel-leave(a)lists.nfs-ganesha.org