Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]


Groups > linux.kernel > #1460614 > unrolled thread

Re: [patch 4 14/22] timer: Switch to a non cascading wheel

Started byJouni Malinen <jkmalinen@gmail.com>
First post2016-08-11 17:30 +0200
Last post2016-08-16 10:00 +0200
Articles 11 — 7 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.


Contents

  Re: [patch 4 14/22] timer: Switch to a non cascading wheel Jouni Malinen <jkmalinen@gmail.com> - 2016-08-11 17:30 +0200
    Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading  wheel rcochran@linutronix.de - 2016-08-11 22:30 +0200
      Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel Jouni Malinen <jkmalinen@gmail.com> - 2016-08-13 11:20 +0200
        Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading  wheel Richard Cochran <richardcochran@gmail.com> - 2016-08-16 11:50 +0200
          Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel Eric Dumazet <edumazet@google.com> - 2016-08-16 16:40 +0200
          Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading  wheel Jouni Malinen <j@w1.fi> - 2016-08-17 11:20 +0200
            Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading  wheel rcochran@linutronix.de - 2016-08-17 11:30 +0200
    Re: [patch 4 14/22] timer: Switch to a non cascading wheel Rik van Riel <riel@redhat.com> - 2016-08-12 20:00 +0200
      Re: [patch 4 14/22] timer: Switch to a non cascading wheel "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-08-12 21:20 +0200
        Re: [patch 4 14/22] timer: Switch to a non cascading wheel Richard Cochran <richardcochran@gmail.com> - 2016-08-16 11:00 +0200
      Re: [patch 4 14/22] timer: Switch to a non cascading wheel Richard Cochran <richardcochran@gmail.com> - 2016-08-16 10:00 +0200

#1460614 — Re: [patch 4 14/22] timer: Switch to a non cascading wheel

FromJouni Malinen <jkmalinen@gmail.com>
Date2016-08-11 17:30 +0200
SubjectRe: [patch 4 14/22] timer: Switch to a non cascading wheel
Message-ID<s505H-5ym-29@gated-at.bofh.it>
On Mon, Jul 4, 2016 at 12:50 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> The current timer wheel has some drawbacks:
...

It looks like this change (commit
500462a9de657f86edaa102f8ab6bff7f7e43fc2 in linux.git) breaks one of
the automated test cases I'm using to test hostapd and wpa_supplicant
with mac80211_hwsim from the kernel. I'm not sure what exactly causes
this (did not really expect git bisect to point to timers..), but this
seems to be very reproducible for me under kvm (though, this
apparently did not happen on another device, so I'm not completely
sure what it is needed to reproduce) with the ap_wps_er_http_proto
test cases failing to connect 20 TCP stream sockets to a server on the
localhost. The client side is a python test script and the server is
hostapd. The failure shows up with about the 13th of those socket
connects failing while all others (both before and after this failed
one) going through.

Would you happen to have any idea why this commit has such a
difference in behavior? I'm currently working around this in my test
script with the following change, but it might be worth while to
confirm whether there is something in the kernel change that resulted
in unexpected behavior.

http://w1.fi/cgit/hostap/commit/?id=2d6a526ac3885605f34df4037fc79ad330565b23

The test code looked like this in python:

    addr = (url.hostname, url.port)
    socks = {}
    for i in range(20):
        socks[i] = socket.socket(socket.AF_INET, socket.SOCK_STREAM,
                                 socket.IPPROTO_TCP)
        socks[i].connect(addr)

With that connect() call being the failing (time out) operation and it
seemed to happen for i == 13 most of the time. This shows up only with
commit 500462a9de657f86edaa102f8ab6bff7f7e43fc2 included in the kernel
(i.e., test with commit b0d6e2dcb284f1f4dcb4b92760f49eeaf5fc0bc7 as
the kernel snapshot does not show this behavior). Changes in 500462a9
were not trivial to revert on top of the current master, so I have not
checked whether the current master branch would get rid of the failure
if only this one commit were reverted.

I can reproduce this easily, so if someone wants to get more details
of the issue, just let me know how to collect whatever would be
useful.

- Jouni

[toc] | [next] | [standalone]


#1460779 — Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel

Fromrcochran@linutronix.de
Date2016-08-11 22:30 +0200
SubjectRe: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel
Message-ID<s54M2-fM-17@gated-at.bofh.it>
In reply to#1460614
On Thu, Aug 11, 2016 at 06:21:26PM +0300, Jouni Malinen wrote:
> The test code looked like this in python:
> 
>     addr = (url.hostname, url.port)
>     socks = {}
>     for i in range(20):
>         socks[i] = socket.socket(socket.AF_INET, socket.SOCK_STREAM,
>                                  socket.IPPROTO_TCP)
>         socks[i].connect(addr)

You getting a timeout on TCP connect()?  Isn't that timeout really
long, like 75 seconds or something?
 
> I can reproduce this easily, so if someone wants to get more details
> of the issue, just let me know how to collect whatever would be
> useful.

Can you provide a simple test case or explain in more detail how you
run your test?  I would like to reproduce the issue it here.

Thanks,
Richard

[toc] | [prev] | [next] | [standalone]


#1461609 — Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel

FromJouni Malinen <jkmalinen@gmail.com>
Date2016-08-13 11:20 +0200
SubjectRe: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel
Message-ID<s5DgK-7o8-9@gated-at.bofh.it>
In reply to#1460779
On Thu, Aug 11, 2016 at 11:25 PM,  <rcochran@linutronix.de> wrote:
> On Thu, Aug 11, 2016 at 06:21:26PM +0300, Jouni Malinen wrote:
>> The test code looked like this in python:
>>
>>     addr = (url.hostname, url.port)
>>     socks = {}
>>     for i in range(20):
>>         socks[i] = socket.socket(socket.AF_INET, socket.SOCK_STREAM,
>>                                  socket.IPPROTO_TCP)
>>         socks[i].connect(addr)
>
> You getting a timeout on TCP connect()?  Isn't that timeout really
> long, like 75 seconds or something?

Yes, it looks like a TCP connect() timeout. I use a significantly
reduced timeout in the test scripts since they are run unattended and
are supposed to terminate in reasonable amount of time.. That said,
this specific test case should not really have used as short a timeout
as it did, i.e., just one second. Interestingly enough, increasing
that to just 1.1 seconds was enough to make the test case pass..
Looking at the time it takes to execute connect(), it is 1.02 - 1.08
seconds for the timing out (with timeout=1sec) case which is now at
i=14 while all the other 19 calls take 0.0 seconds..

If I increase that 20 to 50, I get more of such about 1.03 second
results at i=17, i=34, i=48..

Looking more at what exactly is happening at the TCP layer, this is
likely related to the server behavior since listen() backlog is set to
10 and if there are 10 parallel connections, the last one if
immediately closed before reading anything. Somehow this combination
with this kernel patch applied makes one of the connect() calls take
that surprisingly long 1.02 or so seconds.

Looking at a sniffer capture (*), the three-way TCP connection goes
through fine for the first 15 connect() calls, but the 15th one does
not get a response to SYN. This SYN is the frame 47 in the capture
file with srcport == 60802. There is no SYN,ACK for it. The about one
second unexpected time for connect() comes from this, i.e., the
connection is completed only after the client side does TCP
retransmission of the SYN (frame #77) a second later and the server
side replies with RST,ACK (frame #78).

  2   0.039135    127.0.0.1 -> 127.0.0.1    TCP 74 60772 > 49152 [SYN]
Seq=0 Win=43690 Len=0 MSS=65495 SACK_PERM=1 TSval=4294937755 TSecr=0
WS=64
  3   0.039146    127.0.0.1 -> 127.0.0.1    TCP 74 49152 > 60772 [SYN,
ACK] Seq=0 Ack=1 Win=43690 Len=0 MSS=65495 SACK_PERM=1
TSval=4294937755 TSecr=4294937755 WS=64
  4   0.039156    127.0.0.1 -> 127.0.0.1    TCP 66 60772 > 49152 [ACK]
Seq=1 Ack=1 Win=43712 Len=0 TSval=4294937755 TSecr=4294937755
...
 47   0.042559    127.0.0.1 -> 127.0.0.1    TCP 74 60802 > 49152 [SYN]
Seq=0 Win=43690 Len=0 MSS=65495 SACK_PERM=1 TSval=4294937756 TSecr=0
WS=64
 77   1.119943    127.0.0.1 -> 127.0.0.1    TCP 74 [TCP
Retransmission] 60802 > 49152 [SYN] Seq=0 Win=43690 Len=0 MSS=65495
SACK_PERM=1 TSval=4294937864 TSecr=0 WS=64
 78   1.119953    127.0.0.1 -> 127.0.0.1    TCP 54 49152 > 60802 [RST,
ACK] Seq=1 Ack=1 Win=0 Len=0

So it looks like the issue is in one of the SYN,ACK frames getting
completely lost..

(*) http://w1.fi/p/tcp-lo.pcap

> Can you provide a simple test case or explain in more detail how you
> run your test?  I would like to reproduce the issue it here.

I'm not sure how to make a simple test case for this taken into
account this seems to have some unknown timing dependencies.. A quick
loop of 20 TCP socket() + connect() calls with a server side that does
listen() with backlog 10 and non-blocking operations with 10th and
following incoming sockets getting close() immediately is what the
test case ends up doing, but whether a simple program doing that
without all of python and wpa_supplicant processing giving suitable
timing is unclear..

These files describe the test setup that I'm using to run this:
http://w1.fi/cgit/hostap/plain/tests/hwsim/README
http://w1.fi/cgit/hostap/plain/tests/hwsim/vm/README

with the actual test case being executed with
tests/hwsim/vm$ ./vm-run.sh ap_wps_er_http_proto

- Jouni

[toc] | [prev] | [next] | [standalone]


#1463619 — Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel

FromRichard Cochran <richardcochran@gmail.com>
Date2016-08-16 11:50 +0200
SubjectRe: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel
Message-ID<s6Jap-1oP-1@gated-at.bofh.it>
In reply to#1461609
Jouni,

If I understand the test correctly, then the slightly different kernel
timer behavior is ok, but the test isn't quite right.  Let explain
what I mean.

First off, reading test_ap_wps.py, the point of the test is to see if
ten simultaneous connections are possible.  I guess the server
implements a hard coded limit on the number of clients.  (BTW where is
the server loop?)

You said that the server also sets 'backlog' to ten.  The backlog
controls the size of the queue holding incoming connections that are
in the SYN_RCVD or ESTABLISHED state but have not yet been
accept(2)-ed by the server.  This is *not* the same as the number of
possible simultaneous connections.

On Sat, Aug 13, 2016 at 12:12:26PM +0300, Jouni Malinen wrote:
> Yes, it looks like a TCP connect() timeout. I use a significantly
> reduced timeout in the test scripts since they are run unattended and
> are supposed to terminate in reasonable amount of time.. That said,

I did not find where the client sets the one second timeout.  Where
does this happen?

> If I increase that 20 to 50, I get more of such about 1.03 second
> results at i=17, i=34, i=48..

Can you provide the timings when the test runs on the older kernel?
 
> Looking more at what exactly is happening at the TCP layer, this is
> likely related to the server behavior since listen() backlog is set to
> 10 and if there are 10 parallel connections, the last one if
> immediately closed before reading anything.

To clarify, when the backlog is exceed, the new connection is not
closed.  Instead, the SYN is simply ignored, and the client is expect
to re-transmit the SYN in the normal TCP fashion.

> Looking at a sniffer capture (*), the three-way TCP connection goes
> through fine for the first 15 connect() calls, but the 15th one does
> not get a response to SYN. This SYN is the frame 47 in the capture
> file with srcport == 60802. There is no SYN,ACK for it. The about one
> second unexpected time for connect() comes from this, i.e., the
> connection is completed only after the client side does TCP
> retransmission of the SYN (frame #77) a second later and the server
> side replies with RST,ACK (frame #78).

This is the expected behavior.

> So it looks like the issue is in one of the SYN,ACK frames getting
> completely lost..

No, the frame is not missing.  It was never sent because the backlog
was exceeded.

Here is what I suspect is happening.  By sending 20 SYN frames to a
port with a backlog of 10, it saturates the queue.  One SYN is ignored
by the kernel, and a race begins between the connect() timeout and the
SYN re-transmission.  If the client's re-transmitted SYN and then the
server's SYN,ACK returns before the connect timeout, then the call to
connect() succeeds.  With the new timer wheel, the result of the race
is different.

There a couple of ways to deal with this.  One is to increase the
backlog on the server side.  Another is to increase the connect()
timeout to a multiple of the re-transmission interval.

Thoughts?

Thanks,
Richard

[toc] | [prev] | [next] | [standalone]


#1463856 — Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel

FromEric Dumazet <edumazet@google.com>
Date2016-08-16 16:40 +0200
SubjectRe: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel
Message-ID<s6NH3-4gh-19@gated-at.bofh.it>
In reply to#1463619
On Tue, Aug 16, 2016 at 5:46 AM, Richard Cochran
<richardcochran@gmail.com> wrote:
> Jouni,
>
> If I understand the test correctly, then the slightly different kernel
> timer behavior is ok, but the test isn't quite right.  Let explain
> what I mean.
>
> First off, reading test_ap_wps.py, the point of the test is to see if
> ten simultaneous connections are possible.  I guess the server
> implements a hard coded limit on the number of clients.  (BTW where is
> the server loop?)
>
> You said that the server also sets 'backlog' to ten.  The backlog
> controls the size of the queue holding incoming connections that are
> in the SYN_RCVD or ESTABLISHED state but have not yet been
> accept(2)-ed by the server.  This is *not* the same as the number of
> possible simultaneous connections.
>
> On Sat, Aug 13, 2016 at 12:12:26PM +0300, Jouni Malinen wrote:
>> Yes, it looks like a TCP connect() timeout. I use a significantly
>> reduced timeout in the test scripts since they are run unattended and
>> are supposed to terminate in reasonable amount of time.. That said,
>
> I did not find where the client sets the one second timeout.  Where
> does this happen?
>
>> If I increase that 20 to 50, I get more of such about 1.03 second
>> results at i=17, i=34, i=48..
>
> Can you provide the timings when the test runs on the older kernel?
>
>> Looking more at what exactly is happening at the TCP layer, this is
>> likely related to the server behavior since listen() backlog is set to
>> 10 and if there are 10 parallel connections, the last one if
>> immediately closed before reading anything.
>
> To clarify, when the backlog is exceed, the new connection is not
> closed.  Instead, the SYN is simply ignored, and the client is expect
> to re-transmit the SYN in the normal TCP fashion.
>
>> Looking at a sniffer capture (*), the three-way TCP connection goes
>> through fine for the first 15 connect() calls, but the 15th one does
>> not get a response to SYN. This SYN is the frame 47 in the capture
>> file with srcport == 60802. There is no SYN,ACK for it. The about one
>> second unexpected time for connect() comes from this, i.e., the
>> connection is completed only after the client side does TCP
>> retransmission of the SYN (frame #77) a second later and the server
>> side replies with RST,ACK (frame #78).
>
> This is the expected behavior.
>
>> So it looks like the issue is in one of the SYN,ACK frames getting
>> completely lost..
>
> No, the frame is not missing.  It was never sent because the backlog
> was exceeded.
>
> Here is what I suspect is happening.  By sending 20 SYN frames to a
> port with a backlog of 10, it saturates the queue.  One SYN is ignored
> by the kernel, and a race begins between the connect() timeout and the
> SYN re-transmission.  If the client's re-transmitted SYN and then the
> server's SYN,ACK returns before the connect timeout, then the call to
> connect() succeeds.  With the new timer wheel, the result of the race
> is different.
>
> There a couple of ways to deal with this.  One is to increase the
> backlog on the server side.  Another is to increase the connect()
> timeout to a multiple of the re-transmission interval.
>
> Thoughts?
>

I am coming late to the party, but yes, test looks flaky.

(Relying on having very precise SYN retransmits when listen backlog on
server side is full)

[toc] | [prev] | [next] | [standalone]


#1464431 — Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel

FromJouni Malinen <j@w1.fi>
Date2016-08-17 11:20 +0200
SubjectRe: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel
Message-ID<s75aV-7s7-1@gated-at.bofh.it>
In reply to#1463619
On Tue, Aug 16, 2016 at 11:46:00AM +0200, Richard Cochran wrote:
> If I understand the test correctly, then the slightly different kernel
> timer behavior is ok, but the test isn't quite right.  Let explain
> what I mean.
> 
> First off, reading test_ap_wps.py, the point of the test is to see if
> ten simultaneous connections are possible.  I guess the server
> implements a hard coded limit on the number of clients.  (BTW where is
> the server loop?)

Yes, I think I wrote that test case to hit a specific code path in the
server side. The server implementation is here:
http://w1.fi/cgit/hostap/plain/src/wps/http_server.c

> You said that the server also sets 'backlog' to ten.  The backlog
> controls the size of the queue holding incoming connections that are
> in the SYN_RCVD or ESTABLISHED state but have not yet been
> accept(2)-ed by the server.  This is *not* the same as the number of
> possible simultaneous connections.

This is indeed what seems to be the key area that had a small change in
timing. After some more experimentation on various timing, it is
starting to look like the TCP initiator side retransmission timing is
now different after this kernel commit and that is hit for the case
where the server process does not have enough time to accept() the
incoming connections and listen() backlog ends up dropping it instead.

> On Sat, Aug 13, 2016 at 12:12:26PM +0300, Jouni Malinen wrote:
> > Yes, it looks like a TCP connect() timeout. I use a significantly
> > reduced timeout in the test scripts since they are run unattended and
> > are supposed to terminate in reasonable amount of time.. That said,
> 
> I did not find where the client sets the one second timeout.  Where
> does this happen?

There is a socket.setdefaulttimeout(1) call in wps_er_start().

> > If I increase that 20 to 50, I get more of such about 1.03 second
> > results at i=17, i=34, i=48..
> 
> Can you provide the timings when the test runs on the older kernel?

I had not realized this previously due to the test case passing, but the
same retransmit SYN case was happening with older kernels, it just was
done a tiny bit faster to escape that 1.0 second timeout limit.. That
about 1.03 sec value after this kernel commit is 1.0 sec before this
kernel commit. In other words, something in this specific kernel commit
seems to add about 0.03 sec delay to the TCP SYN retransmission. That
said, I realize that this is quite unlikely timeout to use for connect()
in real world and as such, it looks simply as a side effect of a test
case that was using way too close timing requirement in the first place.

> > Looking more at what exactly is happening at the TCP layer, this is
> > likely related to the server behavior since listen() backlog is set to
> > 10 and if there are 10 parallel connections, the last one if
> > immediately closed before reading anything.
> 
> To clarify, when the backlog is exceed, the new connection is not
> closed.  Instead, the SYN is simply ignored, and the client is expect
> to re-transmit the SYN in the normal TCP fashion.

That closing was referring to what the server code in http_server.c
does, i.e., it does call close() after accept()ing the 10th parallel
connection. I had not realized that this was actually hitting the
listen() backlog in this specific case around the 15th socket, but yes,
that does indeed explain the behavior shown in the sniffer capture.

I was also able to confirm that if I add a short wait in the test loop
between each connect() call, things work fine with this kernel commit
included, i.e., the "issue" was triggered only when this listen()
backlog case was hit.

> Here is what I suspect is happening.  By sending 20 SYN frames to a
> port with a backlog of 10, it saturates the queue.  One SYN is ignored
> by the kernel, and a race begins between the connect() timeout and the
> SYN re-transmission.  If the client's re-transmitted SYN and then the
> server's SYN,ACK returns before the connect timeout, then the call to
> connect() succeeds.  With the new timer wheel, the result of the race
> is different.

Yes, that does indeed look exactly what is happening.

> There a couple of ways to deal with this.  One is to increase the
> backlog on the server side.  Another is to increase the connect()
> timeout to a multiple of the re-transmission interval.

Taken into account this is a test case for testing a specific code path
in http_server.c that is very unlikely to be hit in real world and a way
too short timeout for connect(), it is clear to me that the proper fix
here is to fix the test case to use a longer connect() timeout
especially now that I saw the 1.0 sec time with older kernel as well.

-- 
Jouni Malinen                                            PGP id EFC895FA

[toc] | [prev] | [next] | [standalone]


#1464433 — Re: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel

Fromrcochran@linutronix.de
Date2016-08-17 11:30 +0200
SubjectRe: [PREEMPT-RT] [patch 4 14/22] timer: Switch to a non cascading wheel
Message-ID<s75kB-7vR-7@gated-at.bofh.it>
In reply to#1464431
On Wed, Aug 17, 2016 at 12:05:22PM +0300, Jouni Malinen wrote:
> I had not realized this previously due to the test case passing, but the
> same retransmit SYN case was happening with older kernels, it just was
> done a tiny bit faster to escape that 1.0 second timeout limit.. That
> about 1.03 sec value after this kernel commit is 1.0 sec before this
> kernel commit. In other words, something in this specific kernel commit
> seems to add about 0.03 sec delay to the TCP SYN retransmission.

Yes, and this 3% increase in the timeout expiration interval is an
expected result using the new timer wheel.  See the large comment at
the top of kernel/time/timer.c and the lkml discussion about this
series.

> That
> said, I realize that this is quite unlikely timeout to use for connect()
> in real world and as such, it looks simply as a side effect of a test
> case that was using way too close timing requirement in the first place.

Right, and user space should not rely on the exact timing of TCP SYN
re-transmission!

Thanks,
Richard

[toc] | [prev] | [next] | [standalone]


#1461348

FromRik van Riel <riel@redhat.com>
Date2016-08-12 20:00 +0200
Message-ID<s5oUq-4QH-19@gated-at.bofh.it>
In reply to#1460614

[Multipart message — attachments visible in raw view] — view raw

On Thu, 2016-08-11 at 18:21 +0300, Jouni Malinen wrote:
> On Mon, Jul 4, 2016 at 12:50 PM, Thomas Gleixner <tglx@linutronix.de>
> wrote:
> > The current timer wheel has some drawbacks:
> ...
> 
> It looks like this change (commit
> 500462a9de657f86edaa102f8ab6bff7f7e43fc2 in linux.git) breaks one of
> the automated test cases I'm using to test hostapd and wpa_supplicant
> with mac80211_hwsim from the kernel. I'm not sure what exactly causes
> this (did not really expect git bisect to point to timers..), but
> this
> seems to be very reproducible for me under kvm (though, this
> apparently did not happen on another device, so I'm not completely
> sure what it is needed to reproduce) with the ap_wps_er_http_proto
> test cases failing to connect 20 TCP stream sockets to a server on
> the
> localhost. The client side is a python test script and the server is
> hostapd. The failure shows up with about the 13th of those socket
> connects failing while all others (both before and after this failed
> one) going through.
> 
> Would you happen to have any idea why this commit has such a
> difference in behavior? 

I have a vague hypothesis, more of a question actually.

How does the new timer wheel code handle lost timer ticks?

If a KVM guest does not run for a while, because the host
is scheduling something else, the guest generally only gets
one timer tick after the guest is scheduled back in.

If there are multiple lost ticks, they will remain lost.

Could that cause the new timer wheel code to skip over
timer buckets occasionally, or is this hypothesis bunk?

-- 

All Rights Reversed.

[toc] | [prev] | [next] | [standalone]


#1461427

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2016-08-12 21:20 +0200
Message-ID<s5q9Q-5PW-9@gated-at.bofh.it>
In reply to#1461348
On Fri, Aug 12, 2016 at 01:50:16PM -0400, Rik van Riel wrote:
> On Thu, 2016-08-11 at 18:21 +0300, Jouni Malinen wrote:
> > On Mon, Jul 4, 2016 at 12:50 PM, Thomas Gleixner <tglx@linutronix.de>
> > wrote:
> > > The current timer wheel has some drawbacks:
> > ...
> > 
> > It looks like this change (commit
> > 500462a9de657f86edaa102f8ab6bff7f7e43fc2 in linux.git) breaks one of
> > the automated test cases I'm using to test hostapd and wpa_supplicant
> > with mac80211_hwsim from the kernel. I'm not sure what exactly causes
> > this (did not really expect git bisect to point to timers..), but
> > this
> > seems to be very reproducible for me under kvm (though, this
> > apparently did not happen on another device, so I'm not completely
> > sure what it is needed to reproduce) with the ap_wps_er_http_proto
> > test cases failing to connect 20 TCP stream sockets to a server on
> > the
> > localhost. The client side is a python test script and the server is
> > hostapd. The failure shows up with about the 13th of those socket
> > connects failing while all others (both before and after this failed
> > one) going through.
> > 
> > Would you happen to have any idea why this commit has such a
> > difference in behavior? 
> 
> I have a vague hypothesis, more of a question actually.
> 
> How does the new timer wheel code handle lost timer ticks?
> 
> If a KVM guest does not run for a while, because the host
> is scheduling something else, the guest generally only gets
> one timer tick after the guest is scheduled back in.
> 
> If there are multiple lost ticks, they will remain lost.
> 
> Could that cause the new timer wheel code to skip over
> timer buckets occasionally, or is this hypothesis bunk?

FWIW, I do appear to be seeing more lost wakeups on current mainline
than on v4.7, but not enough of a difference to get a reliable bisction
in reasonable time.

							Thanx, Paul

[toc] | [prev] | [next] | [standalone]


#1463558

FromRichard Cochran <richardcochran@gmail.com>
Date2016-08-16 11:00 +0200
Message-ID<s6Io1-R5-15@gated-at.bofh.it>
In reply to#1461427
On Fri, Aug 12, 2016 at 12:14:11PM -0700, Paul E. McKenney wrote:
> FWIW, I do appear to be seeing more lost wakeups on current mainline
> than on v4.7, but not enough of a difference to get a reliable bisction
> in reasonable time.

We are seeing reproducible hangs* when running Steven's
stress-cpu-hotplug under kvm.  This hang goes back to v4.7 at least.
I couldn't reproduce this with bare metal.  Thomas thought it was a
virtualization issue, not related to the hotplug rework.  He is away
until next week.  Maybe he knows more to say...

To reproduce, run 

   while [ 1 ]; do ./stress-cpu-hotplug ; done

and wait about 20 minutes (or longer).

Thanks,
Richard

* INFO: task cpuhp/7:49 blocked for more than 120 seconds

[toc] | [prev] | [next] | [standalone]


#1463509

FromRichard Cochran <richardcochran@gmail.com>
Date2016-08-16 10:00 +0200
Message-ID<s6HrX-fU-1@gated-at.bofh.it>
In reply to#1461348
On Fri, Aug 12, 2016 at 01:50:16PM -0400, Rik van Riel wrote:
> Could that cause the new timer wheel code to skip over
> timer buckets occasionally, or is this hypothesis bunk?

The new wheel is not different from the old one in this respect.  Each
base keeps its own jiffies counter.  When returning from a long sleep,
the base counter can be behind the current jiffies value by more than
one.  In __run_timers() we loop through all the missed jiffies:

	while (time_after_eq(jiffies, base->clk)) {

		levels = collect_expired_timers(base, heads);
		base->clk++;

		while (levels--)
			expire_timers(base, heads + levels);
	}

So the hypothesis is incorrect.

Thanks,
Richard

[toc] | [prev] | [standalone]


Back to top | Article view | linux.kernel


csiph-web