'Re: Xorg hangs use 99% of CPU on systemd reboot'

[prev in list] [next in list] [prev in thread] [next in thread] 

List: freedesktop-xorg-devel
Subject: Re: Xorg hangs use 99% of CPU on systemd reboot
From: Barry Scott <barry.scott () onelan ! co ! uk>
Date: 2015-07-16 9:21:32
Message-ID: 1599831.D9Wz0DnXTH () f19barry ! office ! onelan ! co ! uk
[Download RAW message or body]

[Attachment #2 (multipart/alternative)]


Opss pressed send not save...

On Wed 15 Jul 2015 13:35:28 Peter Hutterer wrote:
> On Mon, Jul 13, 2015 at 05:18:54PM +0100, Barry Scott wrote:
> > On Fri 03 Jul 2015 16:14:13 Peter Hutterer wrote:
> > > On Thu, Jul 02, 2015 at 04:26:19PM +0100, Barry Scott wrote:
> > > > The attached patch works around an issue we hit after we
> > > > ported from Fedora 20 to Fedora 21.
> > > > 
> > > > When systemd reboot starts something happens to dbus that
> > > > causes Xorg to loop hard using 99% CPU in WaitForSomething.
> > > > 
> > > > The reason for the loop is that the bus_info.fd in dbus-core.c
> > > > has been closed. But the expected Disconnected signal is not
> > > > received by the messages filter.
> > > 
> > > wouldn't it be better to set up the filter so we get the disconnect
> > > signal?
> > 
> > The dbus ping example does not add a filter to see Disconnected.
> > https://github.com/sgh/dbus-examples/blob/master/dbus-ping-listen.c
> 
> looking at config/dbus-core.c, there's message_filter which has the handling
> for the disconnect signal. and the dbus doc says it's always sent. so the
> question is now: did you put printfs into message_filter() to verify that
> the signal never arrives?

The attached dbus-core-logging.patch shows the instrumentation I was using.
You can patch that on top of the proposed fix. I used other logging to show the 
contents of the fd_set's to find that the dbus FD was the problem FD.

> 
> I also notice that message_filter partially shuts down stuff, but it leaves
> bus_info.fd in the select set even though as I understand this is closed
> now. so it seem the RemoveGeneralSocket() and info->fd = -1; call should go
> into message_filter.

The call to teardown() does the necessary cleanup and was the original code.


Barry

> 
> Cheers,
> Peter
> 
> > > > The patch works around this issue by removing the fd from the
> > > > fd_set that is feed into the Select in WaitForSomething by
> > > > calling RemoveGeneralSocket from within wakeup_handler in
> > > > dbus-core.c.
> > > > 
> > > > When systemctl is used to stop and restart Xorg outside of the
> > > > reboot it works without any problems.
> > > > 
> > > > Barry
> > > > 
> > > > 
> > > > From ca770dd6e8ebb9a780ce68a07535f976f6120247 Mon Sep 17 00:00:00 
2001
> > > > From: Barry Scott <barry.scott@onelan.co.uk>
> > > > Date: Tue, 30 Jun 2015 15:58:22 +0100
> > > > Subject: [PATCH] server loops in WaitForSomething when dbus closed by
> > > > systemd>
> > > > 
> > > > shutdown
> > > > 
> > > > Work around issue with dbus fd becoming closed by WaitForSomething
> > > > still using it in Select. The Select return EBADF but becuase the dbus
> > > > fd
> > > > is not taken out of the fs_set the code loop forever.
> > > > 
> > > > This state has been seen when systemd starts to shutdown on Fedora 21.
> > > > 
> > > > Signed-off-by: Barry Scott <barry.scott@onelan.co.uk>
> > > > ---
> > > > 
> > > > config/dbus-core.c | 13 +++++++++++++
> > > > 1 file changed, 13 insertions(+)
> > > > 
> > > > diff --git a/config/dbus-core.c b/config/dbus-core.c
> > > > index 8351ea4..fac8116 100644
> > > > --- a/config/dbus-core.c
> > > > +++ b/config/dbus-core.c
> > > > @@ -52,6 +52,19 @@ wakeup_handler(void *data, int num_fds, void
> > > > *read_mask)
> > > > 
> > > > {
> > > > 
> > > > struct dbus_core_info *info = data;
> > > > 
> > > > + if (info->fd < 0) {
> > > > + return;
> > > > + }
> > > > +
> > > > + if (!dbus_connection_get_is_connected(info->connection)) {
> > > > + /* must remove the FD here as WaitForSomething's Select will
> > > > now
> > > > fail + and WaitForSomething will loop hard calling Select.
> > > > + The "Disconnected" message has been seen to not arrive. */
> > > > + RemoveGeneralSocket(info->fd);
> > > > + info->fd = -1;
> > > > + return;
> > > > + }
> > > > +
> > > > 
> > > > if (info->connection && num_fds > 0 && FD_ISSET(info->fd, (fd_set
> > > > *)
> > > > read_mask)) {>
> > > > 
> > > > do {
> > > > 
> > > > dbus_connection_read_write_dispatch(info->connection, 0);
> > > > 
> > > > _______________________________________________
> > > > xorg-devel@lists.x.org: X.Org development
> > > > Archives: http://lists.x.org/archives/xorg-devel
> > > > Info: http://lists.x.org/mailman/listinfo/xorg-devel


[Attachment #5 (unknown)]

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0//EN" \
"http://www.w3.org/TR/REC-html40/strict.dtd"> <html><head><meta name="qrichtext" \
content="1" /><style type="text/css"> p, li { white-space: pre-wrap; }
</style></head><body style=" font-family:'Monospace'; font-size:10pt; \
font-weight:400; font-style:normal;"> Opss pressed send not save... &nbsp; On Wed 15 Jul 2015 13:35:28 \
Peter Hutterer wrote: &gt; On Mon, Jul 13, 2015 at 05:18:54PM +0100, Barry Scott \
wrote: &gt; &gt; \
On Fri 03 Jul 2015 16:14:13 Peter Hutterer wrote: &gt; &gt; &gt; On Thu, Jul 02, 2015 at 04:26:19PM \
+0100, Barry Scott wrote: &gt; &gt; &gt; &gt; The attached patch works around an issue we \
hit after we &gt; &gt; \
&gt; &gt; ported from Fedora 20 to Fedora 21. &gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; When \
systemd reboot starts something happens to dbus that &gt; &gt; &gt; &gt; causes Xorg to loop hard \
using 99% CPU in WaitForSomething. &gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; The reason for the loop is \
that the bus_info.fd in dbus-core.c &gt; &gt; &gt; &gt; has been closed. But the expected Disconnected \
signal is not &gt; &gt; \
&gt; &gt; received by the messages filter. &gt; &gt; &gt; &gt; &gt; &gt; wouldn't it be better to set up \
the filter so we get the disconnect &gt; &gt; &gt; signal? &gt; &gt; &gt; &gt; The dbus ping example does not add a \
filter to see Disconnected. &gt; &gt; \
https://github.com/sgh/dbus-examples/blob/master/dbus-ping-listen.c &gt; &gt; looking at \
config/dbus-core.c, there's message_filter which has the handling &gt; for the disconnect \
signal. and the dbus doc says it's always sent. so the &gt; question is now: did you put printfs into \
message_filter() to verify that &gt; the signal never arrives? &nbsp; The attached \
dbus-core-logging.patch shows the instrumentation I was using. You can patch that on top of \
the proposed fix. I used other logging to show the contents of the fd_set's to find \
that the dbus FD was the problem FD. &nbsp; &gt; &gt; I also notice that message_filter partially \
shuts down stuff, but it leaves &gt; bus_info.fd in the select set even though as I understand \
this is closed &gt; now. \
so it seem the RemoveGeneralSocket() and info-&gt;fd = -1; call should go &gt; into message_filter. \
&nbsp; \
The call to teardown() does \
the necessary cleanup and was the original code. &nbsp; &nbsp; Barry &nbsp; &gt; &gt; Cheers, &gt; Peter &gt; &gt; &gt; &gt; &gt; The patch \
works around this issue by removing the fd from the &gt; &gt; &gt; &gt; fd_set that is feed into the \
Select in WaitForSomething by &gt; &gt; &gt; &gt; calling RemoveGeneralSocket from within \
wakeup_handler in &gt; &gt; \
&gt; &gt; dbus-core.c. &gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; When systemctl is used to \
stop and restart Xorg outside of the &gt; &gt; &gt; &gt; reboot it works without any \
problems. &gt; &gt; \
&gt; &gt; &gt; &gt; \
&gt; &gt; Barry &gt; &gt; \
&gt; &gt; &gt; &gt; \
&gt; &gt; &gt; &gt; \
&gt; &gt; From ca770dd6e8ebb9a780ce68a07535f976f6120247 Mon Sep 17 00:00:00 2001 \
&gt; &gt; &gt; &gt; From: \
Barry Scott &lt;barry.scott@onelan.co.uk&gt; &gt; &gt; &gt; &gt; Date: Tue, 30 Jun 2015 \
15:58:22 +0100 &gt; &gt; \
&gt; &gt; Subject: [PATCH] server loops in WaitForSomething when dbus closed by \
&gt; &gt; &gt; &gt; \
systemd&gt; &gt; &gt; \
&gt; &gt; &gt; &gt; \
&gt; &gt; shutdown &gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; Work around issue with dbus \
fd becoming closed by WaitForSomething &gt; &gt; &gt; &gt; still using it in Select. The \
Select return EBADF but becuase the dbus &gt; &gt; &gt; &gt; fd &gt; &gt; &gt; &gt; is not \
taken out of the fs_set the code loop forever. &gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; This \
state has been seen when systemd starts to shutdown on Fedora 21. &gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; \
Signed-off-by: Barry Scott &lt;barry.scott@onelan.co.uk&gt; &gt; &gt; &gt; &gt; --- \
&gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; \
config/dbus-core.c | 13 +++++++++++++ &gt; &gt; &gt; &gt; 1 file changed, 13 \
insertions(+) &gt; &gt; \
&gt; &gt; &gt; &gt; \
&gt; &gt; diff --git a/config/dbus-core.c b/config/dbus-core.c &gt; &gt; &gt; &gt; index \
8351ea4..fac8116 100644 &gt; &gt; &gt; &gt; --- a/config/dbus-core.c &gt; &gt; &gt; &gt; +++ \
b/config/dbus-core.c <p style=" margin-top:0px; margin-bottom:0px; \
margin-left:0px; margin-right:0px; -qt-block-indent:0; text-indent:0px; \
&gt; &gt; &gt; &gt; \
*read_mask) &gt; &gt; \
&gt; &gt; &gt; &gt; \
&gt; &gt; { &gt; &gt; \
&gt; &gt; &gt; &gt; \
&gt; &gt; struct dbus_core_info *info = data; &gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; + if \
(info-&gt;fd &lt; 0) { &gt; &gt; &gt; &gt; + return; &gt; &gt; &gt; &gt; + \
} &gt; &gt; \
&gt; &gt; + &gt; &gt; \
&gt; &gt; + if (!dbus_connection_get_is_connected(info-&gt;connection)) { &gt; &gt; &gt; &gt; + \
/* must remove the FD here as WaitForSomething's Select will &gt; &gt; &gt; &gt; now \
&gt; &gt; &gt; &gt; fail + \
and WaitForSomething will loop hard calling Select. &gt; &gt; &gt; &gt; + The \
&quot;Disconnected&quot; message has been seen to not arrive. */ &gt; &gt; &gt; &gt; + \
RemoveGeneralSocket(info-&gt;fd); &gt; &gt; &gt; &gt; + info-&gt;fd = -1; &gt; &gt; &gt; &gt; + \
return; &gt; &gt; \
&gt; &gt; + } &gt; &gt; \
&gt; &gt; + &gt; &gt; \
&gt; &gt; &gt; &gt; \
&gt; &gt; if (info-&gt;connection &amp;&amp; num_fds &gt; 0 &amp;&amp; \
FD_ISSET(info-&gt;fd, (fd_set &gt; &gt; &gt; &gt; *) &gt; &gt; &gt; &gt; read_mask)) {&gt; &gt; &gt; &gt; &gt; \
&gt; &gt; &gt; &gt; \
do { &gt; &gt; \
&gt; &gt; &gt; &gt; &gt; &gt; \
dbus_connection_read_write_dispatch(info-&gt;connection, 0); &gt; &gt; &gt; &gt; &gt; &gt; &gt; &gt; \
_______________________________________________ &gt; &gt; &gt; &gt; xorg-devel@lists.x.org: X.Org \
development &gt; &gt; \
&gt; &gt; Archives: http://lists.x.org/archives/xorg-devel &gt; &gt; &gt; &gt; Info: \
http://lists.x.org/mailman/listinfo/xorg-devel &nbsp;</body></html>


["dbus-core-logging.patch" (dbus-core-logging.patch)]

--- xorg-server-1.16.3/config/dbus-core.c	2015-06-30 15:33:34.330316950 +0100
+++ xorg-server-1.16.3.patched/config/dbus-core.c	2015-06-30 15:18:12.265645848 +0100
@@ -65,13 +65,20 @@
         return;
     }
 
-    if (info->connection && num_fds > 0 && FD_ISSET(info->fd, (fd_set *) read_mask)) \
{ +    if (dbus_connection_get_is_connected(info->connection) && num_fds > 0 && \
FD_ISSET(info->fd, (fd_set *) read_mask)) { +        LogMessage( X_ERROR, \
"[dbus-core] wakeup_handler start connected %d fd %d in read_mask\n", +               \
dbus_connection_get_is_connected(info->connection), info->fd ); +
         do {
             dbus_connection_read_write_dispatch(info->connection, 0);
         } while (info->connection &&
                  dbus_connection_get_is_connected(info->connection) &&
                  dbus_connection_get_dispatch_status(info->connection) ==
                  DBUS_DISPATCH_DATA_REMAINS);
+
+        LogMessage( X_ERROR, "[dbus-core] wakeup_handler end connected %d fd %d\n",
+                dbus_connection_get_is_connected(info->connection), info->fd );
+
     }
 }
 
@@ -89,6 +96,8 @@
 {
     struct dbus_core_hook *hook;
 
+    LogMessage( X_ERROR, "[dbus-core] teardown fd=%d\n", bus_info.fd );
+
     if (bus_info.timer) {
         TimerFree(bus_info.timer);
         bus_info.timer = NULL;
@@ -121,11 +130,52 @@
 static DBusHandlerResult
 message_filter(DBusConnection * connection, DBusMessage * message, void *data)
 {
+    const char *dbg_info;
+
+    LogMessage( X_ERROR, "[dbus-core] message filter fd=%d type=%d interface=%s \
message=%s\n", +                bus_info.fd, dbus_message_get_type( message ), \
dbus_message_get_interface( message ), +                dbus_message_get_member( \
message ) ); +    dbg_info = dbus_message_get_destination( message );
+    if( dbg_info!= NULL ) {
+        LogMessage( X_ERROR, "[dbus-core] destination=%s\n", dbg_info );
+    }
+    dbg_info = dbus_message_get_path( message );
+    if( dbg_info!= NULL ) {
+        LogMessage( X_ERROR, "[dbus-core] path=%s\n", dbg_info );
+    }
+    dbg_info = dbus_message_get_member( message );
+    if( dbg_info!= NULL ) {
+        LogMessage( X_ERROR, "[dbus-core] member=%s\n", dbg_info );
+    }
+    dbg_info = dbus_message_get_sender( message );
+    if( dbg_info!= NULL ) {
+        LogMessage( X_ERROR, "[dbus-core] sender=%s\n", dbg_info );
+    }
+    dbg_info = dbus_message_get_signature( message );
+    if( dbg_info!= NULL ) {
+        LogMessage( X_ERROR, "[dbus-core] signature=%s\n", dbg_info );
+    }
+
+    if (dbus_message_is_signal(message, dbus_message_get_interface( message ), \
"NameAcquired")) { +        DBusError error;
+        char *name;
+
+        dbus_error_init( &error );
+        dbus_message_get_args( message, &error, DBUS_TYPE_STRING, &name, \
DBUS_TYPE_INVALID ); +        if( dbus_error_is_set(&error) ) {
+            LogMessage( X_ERROR, "[dbus-core] failed to get arg: %s\n", \
error.message ); +        } else {
+            LogMessage( X_ERROR, "[dbus-core] NameAquired( %s )\n", name );
+        }
+
+        dbus_error_free(&error);
+    }
+
     /* If we get disconnected, then take everything down, and attempt to
      * reconnect immediately (assuming it's just a restart).  The
      * connection isn't valid at this point, so throw it out immediately. */
     if (dbus_message_is_signal(message, DBUS_INTERFACE_LOCAL, "Disconnected")) {
-        DebugF("[dbus-core] disconnected from bus\n");
+        LogMessage( X_ERROR, "[dbus-core] disconnected from bus\n");
         bus_info.connection = NULL;
         teardown();
 
@@ -133,9 +183,12 @@
             TimerFree(bus_info.timer);
         bus_info.timer = TimerSet(NULL, 0, 1, reconnect_timer, NULL);
 
+        LogMessage( X_ERROR, "[dbus-core] message filter done \
DBUS_HANDLER_RESULT_HANDLED\n" );  return DBUS_HANDLER_RESULT_HANDLED;
     }
 
+    LogMessage( X_ERROR, "[dbus-core] message filter done \
DBUS_HANDLER_RESULT_NOT_YET_HANDLED\n" ); +
     return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
 }
 
@@ -167,6 +220,8 @@
         goto err_unref;
     }
 
+    LogMessage( X_ERROR, "[dbus-core] dbus system bus fd is %d\n", bus_info.fd );
+
     if (!dbus_connection_add_filter(bus_info.connection, message_filter,
                                     &bus_info, NULL)) {
         ErrorF("[dbus-core] couldn't add filter: %s (%s)\n", error.name,


[Attachment #7 (text/plain)]

_______________________________________________
xorg-devel@lists.x.org: X.Org development
Archives: http://lists.x.org/archives/xorg-devel
Info: http://lists.x.org/mailman/listinfo/xorg-devel

[prev in list] [next in list] [prev in thread] [next in thread] 
