sys_epoll_wait high CPU load in 2.6.37

Hello!

Since upgrading 2.6.36 -> 2.6.37, dovecot's "anvil" process seems to end up taking a lot more time in "top", and "perf top" shows output like this (system-wide):

samples pcnt function DSO
_______ _____ _____________________________ __________________________

  2405.00 68.8% sys_epoll_wait                [kernel.kallsyms]
    33.00  0.9% mail_cache_lookup_iter_next   libdovecot-storage.so.0.0.0
    30.00  0.9% _raw_spin_lock                [kernel.kallsyms]
    ...etc...

It only wakes up 5-10 times per second or so (on this box), and does stuff like this:

epoll_wait(12, {{EPOLLIN, {u32=19417616, u64=19417616}}}, 25, 2147483647) = 1 read(29, "PENALTY-GET\t192.168.31.10\n"..., 738) = 26
write(29, "0 0\n"..., 4) = 4
epoll_wait(12, {{EPOLLIN, {u32=19395632, u64=19395632}}}, 25, 2147483647) = 1 read(18, "LOOKUP\tpop3/192.168.31.10/tshield"..., 668) = 58
write(18, "0\n"..., 2) = 2
epoll_wait(12, {{EPOLLIN, {u32=19373072, u64=19373072}}}, 25, 2147483647) = 1 read(7, "CONNECT\t3490\tpop3/192.168.31.10/t"..., 254) = 64 epoll_wait(12, {{EPOLLIN, {u32=19373072, u64=19373072}}}, 25, 2147483647) = 1 read(7, "DISCONNECT\t3482\tpop3/192.168.31.1"..., 190) = 62

Anything obvious here? anvil talks over UNIX sockets to the rest of dovecot, and uses epoll_wait. So, suspect commits might be:

95aac7b1cd224f568fb83937044cd303ff11b029 5456f09aaf88731e16dbcea7522cb330b6846415
or other bits from
git log v2.6.36..v2.6.37 net/unix/af_unix.c fs/eventpoll.c

I suspect it has something to do with that "infinite value" check removal in that first commit. It doesn't show up easily on a test box, but I can try reverting 95aac7b1cd in production if it's not obvious.

Simon-

Quoted 40 lines · Simon Kirby

Hello!

Since upgrading 2.6.36 -> 2.6.37, dovecot's "anvil" process seems to end up taking a lot more time in "top", and "perf top" shows output like this (system-wide):

samples pcnt function DSO
_______ _____ _____________________________ __________________________

  2405.00 68.8% sys_epoll_wait                [kernel.kallsyms]
    33.00  0.9% mail_cache_lookup_iter_next   libdovecot-storage.so.0.0.0
    30.00  0.9% _raw_spin_lock                [kernel.kallsyms]
    ...etc...

It only wakes up 5-10 times per second or so (on this box), and does stuff like this:

epoll_wait(12, {{EPOLLIN, {u32=19417616, u64=19417616}}}, 25, 2147483647) = 1 read(29, "PENALTY-GET\t192.168.31.10\n"..., 738) = 26
write(29, "0 0\n"..., 4) = 4
epoll_wait(12, {{EPOLLIN, {u32=19395632, u64=19395632}}}, 25, 2147483647) = 1 read(18, "LOOKUP\tpop3/192.168.31.10/tshield"..., 668) = 58
write(18, "0\n"..., 2) = 2
epoll_wait(12, {{EPOLLIN, {u32=19373072, u64=19373072}}}, 25, 2147483647) = 1 read(7, "CONNECT\t3490\tpop3/192.168.31.10/t"..., 254) = 64 epoll_wait(12, {{EPOLLIN, {u32=19373072, u64=19373072}}}, 25, 2147483647) = 1 read(7, "DISCONNECT\t3482\tpop3/192.168.31.1"..., 190) = 62

Anything obvious here? anvil talks over UNIX sockets to the rest of dovecot, and uses epoll_wait. So, suspect commits might be:

95aac7b1cd224f568fb83937044cd303ff11b029 5456f09aaf88731e16dbcea7522cb330b6846415
or other bits from
git log v2.6.36..v2.6.37 net/unix/af_unix.c fs/eventpoll.c

I suspect it has something to do with that "infinite value" check removal in that first commit. It doesn't show up easily on a test box, but I can try reverting 95aac7b1cd in production if it's not obvious.

Quoted 1 line

Simon-

Yes, 95aac7b1cd is the problem, but anvil should use a 0 (no) timeout instead of 2147483647 ms : epoll_wait() doesnt have to arm a timer in this case, it is a bit faster.

Quoted 41 lines · Eric Dumazet

Quoted 40 lines · Simon Kirby

Hello!

Since upgrading 2.6.36 -> 2.6.37, dovecot's "anvil" process seems to end up taking a lot more time in "top", and "perf top" shows output like this (system-wide):

samples pcnt function DSO
_______ _____ _____________________________ __________________________

  2405.00 68.8% sys_epoll_wait                [kernel.kallsyms]
    33.00  0.9% mail_cache_lookup_iter_next   libdovecot-storage.so.0.0.0
    30.00  0.9% _raw_spin_lock                [kernel.kallsyms]
    ...etc...

It only wakes up 5-10 times per second or so (on this box), and does stuff like this:

epoll_wait(12, {{EPOLLIN, {u32=19417616, u64=19417616}}}, 25, 2147483647) = 1 read(29, "PENALTY-GET\t192.168.31.10\n"..., 738) = 26
write(29, "0 0\n"..., 4) = 4
epoll_wait(12, {{EPOLLIN, {u32=19395632, u64=19395632}}}, 25, 2147483647) = 1 read(18, "LOOKUP\tpop3/192.168.31.10/tshield"..., 668) = 58
write(18, "0\n"..., 2) = 2
epoll_wait(12, {{EPOLLIN, {u32=19373072, u64=19373072}}}, 25, 2147483647) = 1 read(7, "CONNECT\t3490\tpop3/192.168.31.10/t"..., 254) = 64 epoll_wait(12, {{EPOLLIN, {u32=19373072, u64=19373072}}}, 25, 2147483647) = 1 read(7, "DISCONNECT\t3482\tpop3/192.168.31.1"..., 190) = 62

Anything obvious here? anvil talks over UNIX sockets to the rest of dovecot, and uses epoll_wait. So, suspect commits might be:

95aac7b1cd224f568fb83937044cd303ff11b029 5456f09aaf88731e16dbcea7522cb330b6846415
or other bits from
git log v2.6.36..v2.6.37 net/unix/af_unix.c fs/eventpoll.c

I suspect it has something to do with that "infinite value" check removal in that first commit. It doesn't show up easily on a test box, but I can try reverting 95aac7b1cd in production if it's not obvious.

Quoted 7 lines

Quoted 1 line

Simon-

Yes, 95aac7b1cd is the problem, but anvil should use a 0 (no) timeout instead of 2147483647 ms : epoll_wait() doesnt have to arm a timer in this case, it is a bit faster.

Slowness comes from timespec_add_ns() : This one assumed small 'ns' argument, since it wants to avoid a divide instruction.

static __always_inline void timespec_add_ns(struct timespec *a, u64 ns)

{
        a->tv_sec += __iter_div_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
        a->tv_nsec = ns;
}

We should do this differently for epoll usage ;)

Please try following patch :

[PATCH] epoll: epoll_wait() should be careful in timespec_add_ns use

commit 95aac7b1cd224f (epoll: make epoll_wait() use the hrtimer range feature) added a performance regression because it used timespec_add_ns() with potential very large 'ns' values.

Reported-by Simon Kirby <[email protected]>

Signed-off-by Eric Dumazet <[email protected]>

CC Shawn Bohrer <[email protected]>

CC Davide Libenzi <[email protected]>

CC Andrew Morton <[email protected]>

---
 fs/eventpoll.c |    4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

fs/eventpoll.c +0 -0

index cc8a9b7..7ec0890 100644

Quoted 6 lines · Eric Dumazet

fs/eventpoll.c +0 -0

index cc8a9b7..7ec0890 100644
@@ -1126,7 +1126,9 @@ static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events,
 

fs/eventpoll.c static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events, · line 1134

Quoted 9 lines

fs/eventpoll.c +3 -1

 	if (timeout > 0) {
 		ktime_get_ts(&end_time);
-		timespec_add_ns(&end_time, (u64)timeout * NSEC_PER_MSEC);
+		end_time.tv_sec += timeout / MSEC_PER_SEC;
+		timeout %= MSEC_PER_SEC;
+		timespec_add_ns(&end_time, timeout * NSEC_PER_MSEC);
 		slack = select_estimate_accuracy(&end_time);
 		to = &expires;
 		*to = timespec_to_ktime(end_time);

Yep, we can overflow the timeout, with the calculation above. A timespec_add_ms()?

Quoted 9 lines · Davide Libenzi

Quoted 6 lines · Eric Dumazet

fs/eventpoll.c +0 -0

index cc8a9b7..7ec0890 100644
@@ -1126,7 +1126,9 @@ static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events,
 

Quoted 12 lines

fs/eventpoll.c static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events, · line 1134

Quoted 9 lines

fs/eventpoll.c +3 -1

 	if (timeout > 0) {
 		ktime_get_ts(&end_time);
-		timespec_add_ns(&end_time, (u64)timeout * NSEC_PER_MSEC);
+		end_time.tv_sec += timeout / MSEC_PER_SEC;
+		timeout %= MSEC_PER_SEC;
+		timespec_add_ns(&end_time, timeout * NSEC_PER_MSEC);
 		slack = select_estimate_accuracy(&end_time);
 		to = &expires;
 		*to = timespec_to_ktime(end_time);

Yep, we can overflow the timeout, with the calculation above. A timespec_add_ms()?

Well, given timeout after modulo contains a number between 0 and 999, multiply by 1.000.000 (NSEC_PER_MSEC) cant overflow.

For "above", I meant the current epoll expire time calculation, which was described above in the message ;)

The hint for a timespec_add_ms() was because we must be doing something similar in poll, don't we (/me got no code in front ATM)?

Quoted 2 lines · Davide Libenzi

For "above", I meant the current epoll expire time calculation, which was described above in the message ;)

Well, problem was not an overflow, but doing a loop 2.000.000 times ;)

Quoted 2 lines

The hint for a timespec_add_ms() was because we must be doing something similar in poll, don't we (/me got no code in front ATM)?

Apparently its done differently in poll(), using
poll_select_set_timeout() helper.

Give me some minutes I'll try to cook an alternate patch

Quoted 7 lines · Eric Dumazet

Quoted 2 lines · Davide Libenzi

For "above", I meant the current epoll expire time calculation, which was described above in the message ;)

Well, problem was not an overflow, but doing a loop 2.000.000 times ;)

Quoted 9 lines

Quoted 2 lines

The hint for a timespec_add_ms() was because we must be doing something similar in poll, don't we (/me got no code in front ATM)?

Apparently its done differently in poll(), using
poll_select_set_timeout() helper.

Give me some minutes I'll try to cook an alternate patch

Here is the alternate patch, using poll_select_set_timeout() helper

Thanks

[PATCH v2] epoll: epoll_wait() should not use timespec_add_ns()

commit 95aac7b1cd224f (epoll: make epoll_wait() use the hrtimer range feature) added a performance regression because it uses timespec_add_ns() with potential very large 'ns' values.

Use poll_select_set_timeout() helper like poll()/select()

Reported-by Simon Kirby <[email protected]>

Signed-off-by Eric Dumazet <[email protected]>

CC Shawn Bohrer <[email protected]>

CC Davide Libenzi <[email protected]>

CC Thomas Gleixner <[email protected]>

CC Andrew Morton <[email protected]>

---
 fs/eventpoll.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

fs/eventpoll.c +0 -0

index cc8a9b7..94d887b 100644

Quoted 47 lines · Eric Dumazet

Quoted 7 lines · Eric Dumazet

Quoted 2 lines · Davide Libenzi

For "above", I meant the current epoll expire time calculation, which was described above in the message ;)

Well, problem was not an overflow, but doing a loop 2.000.000 times ;)

Quoted 9 lines

Quoted 2 lines

The hint for a timespec_add_ms() was because we must be doing something similar in poll, don't we (/me got no code in front ATM)?

Apparently its done differently in poll(), using
poll_select_set_timeout() helper.

Give me some minutes I'll try to cook an alternate patch

Here is the alternate patch, using poll_select_set_timeout() helper

Thanks

[PATCH v2] epoll: epoll_wait() should not use timespec_add_ns()

commit 95aac7b1cd224f (epoll: make epoll_wait() use the hrtimer range feature) added a performance regression because it uses timespec_add_ns() with potential very large 'ns' values.

Use poll_select_set_timeout() helper like poll()/select()

Reported-by Simon Kirby <[email protected]>

Signed-off-by Eric Dumazet <[email protected]>

CC Shawn Bohrer <[email protected]>

CC Davide Libenzi <[email protected]>

CC Thomas Gleixner <[email protected]>

CC Andrew Morton <[email protected]>

---
 fs/eventpoll.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

fs/eventpoll.c +0 -0

index cc8a9b7..94d887b 100644
@@ -1125,8 +1125,8 @@ static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events,
 	ktime_t expires, *to = NULL;
 

fs/eventpoll.c static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events, · line 1132

Quoted 8 lines

fs/eventpoll.c +2 -2

 	if (timeout > 0) {
-		ktime_get_ts(&end_time);
-		timespec_add_ns(&end_time, (u64)timeout * NSEC_PER_MSEC);
+		poll_select_set_timeout(&end_time, timeout / MSEC_PER_SEC,
+				NSEC_PER_MSEC * (timeout % MSEC_PER_SEC));
 		slack = select_estimate_accuracy(&end_time);
 		to = &expires;
 		*to = timespec_to_ktime(end_time);

poll_select_set_timeout() jumps through some extra hoops that aren't necessary in the epoll case so I actually like your previous patch better.

Quoted 5 lines

Quoted 5 lines

fs/eventpoll.c +0 -0

@@ -1125,8 +1125,8 @@ static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events,
 	ktime_t expires, *to = NULL;
 

Quoted 12 lines

fs/eventpoll.c static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events, · line 1132

Quoted 8 lines

fs/eventpoll.c +2 -2

 	if (timeout > 0) {
-		ktime_get_ts(&end_time);
-		timespec_add_ns(&end_time, (u64)timeout * NSEC_PER_MSEC);
+		poll_select_set_timeout(&end_time, timeout / MSEC_PER_SEC,
+				NSEC_PER_MSEC * (timeout % MSEC_PER_SEC));
 		slack = select_estimate_accuracy(&end_time);
 		to = &expires;
 		*to = timespec_to_ktime(end_time);

poll_select_set_timeout() jumps through some extra hoops that aren't necessary in the epoll case so I actually like your previous patch better.

Well, I dont care, I let Davide decide, he is the boss ;)

This is a stable candidate, so adding timespec_add_ms() sounds overkill.

Eric, if you look at fs/select.c (~line 925), poll does exactly the same thing as epoll do.
It too, ignores the eventual return value of poll_select_set_timeout(), so maybe a little bit more optimized ktime_get_ts+timespec_add_ms could make sense.

Quoted 6 lines · Davide Libenzi

Eric, if you look at fs/select.c (~line 925), poll does exactly the same thing as epoll do.
It too, ignores the eventual return value of poll_select_set_timeout(), so maybe a little bit more optimized ktime_get_ts+timespec_add_ms could make sense.

OK, I'll post a V3 ;)

Quoted 10 lines · Eric Dumazet

Quoted 6 lines · Davide Libenzi

Eric, if you look at fs/select.c (~line 925), poll does exactly the same thing as epoll do.
It too, ignores the eventual return value of poll_select_set_timeout(), so maybe a little bit more optimized ktime_get_ts+timespec_add_ms could make sense.

OK, I'll post a V3 ;)

Well in the poll() case we handle a zero timeout, not in epoll().

So the helper function cannot be shared and can be static to epoll.

[PATCH v3] epoll: epoll_wait() should not use timespec_add_ns()

commit 95aac7b1cd224f (epoll: make epoll_wait() use the hrtimer range feature) added a performance regression because it uses timespec_add_ns() with potential very large 'ns' values.

Reported-by Simon Kirby <[email protected]>

Signed-off-by Eric Dumazet <[email protected]>

CC Shawn Bohrer <[email protected]>

CC Davide Libenzi <[email protected]>

CC Thomas Gleixner <[email protected]>

CC Andrew Morton <[email protected]>

---
 fs/eventpoll.c |   16 +++++++++++++---
 1 file changed, 13 insertions(+), 3 deletions(-)

fs/eventpoll.c +11 -1

index cc8a9b7..d517aa3 100644
@@ -1114,6 +1114,17 @@ static int ep_send_events(struct eventpoll *ep,
 	return ep_scan_ready_list(ep, ep_send_events_proc, &esed);
 }
 
+static inline struct timespec epoll_set_mstimeout(long ms)
+{
+	struct timespec now, ts = {
+		.tv_sec = ms / MSEC_PER_SEC,
+		.tv_nsec = NSEC_PER_MSEC * (ms % MSEC_PER_SEC),
+	};
+
+	ktime_get_ts(&now);
+	return timespec_add_safe(now, ts);
+}
+
 static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events,
 		   int maxevents, long timeout)
 {

@@ -1121,12 +1132,11 @@ static int ep_poll(struct eventpoll *ep, struct epoll_event __user *events,
 	unsigned long flags;
 	long slack;
 	wait_queue_t wait;
-	struct timespec end_time;