ManagedSelector dump improvements from #1970 #2062

gregw · 2017-12-14T22:29:33Z

ManagedSelector dump improvements from #1970:

DumpKeys is now prepended to actions list so it is less likely to be delayed by a stuck/busy selector
Timestamps are included for actions and keys which may be separated by time
Race removed race for updating dumpKey list while it is being added to.

Signed-off-by: Greg Wilkins gregw@webtide.com

ManagedSelector dump improvements from #1970: + DumpKeys is now prepended to actions list so it is less likely to be delayed by a stuck/busy selector + Timestamps are included for actions and keys which may be separated by time + Race removed race for updating dumpKey list while it is being added to. Signed-off-by: Greg Wilkins <gregw@webtide.com>

sbordet · 2017-12-19T16:32:06Z

jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java

@@ -45,6 +46,7 @@
 import org.eclipse.jetty.util.component.DumpableCollection;
 import org.eclipse.jetty.util.log.Log;
 import org.eclipse.jetty.util.log.Logger;
+import org.eclipse.jetty.util.log.StdErrLog;


Uh, no. We don't want a core class like ManagedSelector depend on a concrete implementation of our logging.
StdErrLog is never used directly apart in tests or configuration files, and must remain so.

Why? It's part of util. I think it is reasonable to use common date formatting code, specially as it means date cache can be used. I guess I can move the method to a common logging class

Not good because in light of JDK 9 modules StdErrLog will be a private class that we don't export, or something like that. Really, this is just formatting a date in case of dumping, the JDK has plenty of methods that do that, we don't need another utility method used only here.

sbordet · 2017-12-19T16:37:45Z

jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java

            try (Locker.Lock lock = _locker.lock())
            {
+                actionsAt = StdErrLog.timestamp(System.currentTimeMillis(),TimeUnit.MILLISECONDS);


We can format a date using java.time from JDK 8.

That will result in a different timestamp and also will not use the date formatting cache used by stderrlog.

What different timestamp ? And why we should care at all about what StdErrLog does ? We change StdErrLog we break here ? I don't understand why we cannot use the JDK to format a date/time.

I don't want to use JDK to format the time here as it will be a different format to what we are using in our logging and it will not use our dateCache, which is designed to help with formatting many similar times per second.

I'll move the method to be on Log, which will always be a public class.

This is a JMX method. It does not get logged. It is reported in the JMX console where people copy&paste it into an editor. It does not have to have anything that is related to our logging implementation. And besides, most of the deployments will use another logging system that is not ours, so the format of the date will be different anyway.
I'm against this, and moving it to Log is even worse because this is a formatting concern now exposed into a public class.

sbordet · 2017-12-19T16:38:58Z

jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java

+        }
+        else
+        {
+            dumpBeans(out,indent);


Call super.dump(out, indent) instead ?

No, that results in badly formatted output. This is the core of this fix.

Calling super results in calling dumpBeans() so the formatting will be identical.
This method overrides the behavior of the super class to add the dump of the keys.
I think it's better written by always calling super, and then dumping the keys by calling dump(out, indent, Collection).

sbordet · 2017-12-19T16:40:08Z

jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java

+            keys = dump.get(5, TimeUnit.SECONDS);
+            String keysAt = StdErrLog.timestamp(System.currentTimeMillis(),TimeUnit.MILLISECONDS);
+            if (keys==null)
+                keys = Collections.singletonList("NO DUMP RESPONSE");


Improve the message... Must have normal case and explain that it's the keys dump that we did not get a response from, and add how long we waited, etc.

sbordet · 2017-12-19T16:44:50Z

jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java

+            if (keys==null)
+                keys = Collections.singletonList("NO DUMP RESPONSE");
+            dumpBeans(out, indent, Arrays.asList(new DumpableCollection("actions @ "+actionsAt, actions),
+                    new DumpableCollection("keys @ "+keysAt, keys) ));


I'm not sure I understand the 2 timestamps actionsAt and keysAt what information they give ?

It takes time to retrieve the keys, so the actions and keys are from different instance. Logging here so we know what that is.

sbordet · 2017-12-19T16:52:15Z

jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java

-            this._dumps = dumps;
-        }
-
+        private final Exchanger<List<String>> _dump = new Exchanger<>();


I don't like using an Exchanger instead of a CountDownLatch.
The reason is that the exchanger may block the thread that runs the DumpKeys action (see below, 500 ms hardcoded), while CountDownLatch never blocks it.

So may grabbing the lock above and we do that.

What lock ? The previous implementation was just calling CountDownLatch.countDown(), no locks, no wait, nothing.
The JMX thread was waiting, not the selector thread. Now we have the selector thread possibly waiting 500 ms if the JMX thread is for some reason late to arrive at the exchanger (GC, scheduling, etc.).

Submitting the dumpkeys class grabs the lock

sbordet · 2017-12-19T16:53:46Z

jetty-util/src/main/java/org/eclipse/jetty/util/component/DumpableCollection.java

@@ -48,4 +55,18 @@ public void dump(Appendable out, String indent) throws IOException
        if (_collection!=null)
            ContainerLifeCycle.dump(out,indent,_collection);
    }
+
+    public static class DumpableThread extends DumpableCollection


This class is never used ? Not in this PR however, so it must not be in this PR.

It is used by the updated dump in ManagedSelector

Where ? I can't see it in this PR.

Oh sorry, thought you were referring to DumpableCollection. You are right about DumpableThread.

sbordet · 2017-12-19T16:54:15Z

jetty-util/src/main/java/org/eclipse/jetty/util/log/StdErrLog.java

@@ -145,6 +146,32 @@ public static void setTagPad(int pad)
    protected final String _abbrevname;
    private boolean _hideStacks = false;

+    public static String timestamp(long time, TimeUnit units)


Against this utility method, see comments above.

Against the method or it's location?

Both. We don't need it. Use JDK to format dates.

Signed-off-by: Greg Wilkins <gregw@webtide.com>

sbordet · 2017-12-20T10:47:02Z

jetty-util/src/main/java/org/eclipse/jetty/util/log/Log.java

+     * @param units The units of the time
+     * @return The formatted time string.
+     */
+    public static String timestamp(long time, TimeUnit units)


Nope. Not needed, wrong place, implementation detail exposed into a public class.

Signed-off-by: Greg Wilkins <gregw@webtide.com>

gregw · 2017-12-27T13:47:33Z

@sbordet have I addressed your concerns? Can I merge?

sbordet · 2017-12-27T16:27:28Z

jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java

        @Override
        public void run()
        {
            Selector selector = _selector;
+            List<String> list = new ArrayList<>(selector.keys().size()+1);


This is not right, since selector may be null and will produce a NPE here. Move it inside the if statement below, and you will also already have the keys set.

sbordet · 2017-12-27T16:28:58Z

jetty-util/src/main/java/org/eclipse/jetty/util/component/DumpableCollection.java

@@ -34,6 +35,12 @@ public DumpableCollection(String name,Collection<?> collection)
        _name=name;
        _collection=collection;
    }
+
+    public DumpableCollection(String name,Object... item)


This new constructor is never used. Seems a leftover from some previous refactoring, so I would remove it.

sbordet · 2017-12-27T16:30:01Z

jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java

+            if (keys==null)
+                keys = Collections.singletonList("No dump keys retrieved");
+            dumpBeans(out, indent, Arrays.asList(new DumpableCollection("actions @ "+actionsAt, actions),
+                    new DumpableCollection("keys @ "+keysAt, keys) ));


Unneeded extra space after keys).

sbordet · 2017-12-27T16:31:53Z

@gregw not good yet, I requested some more changes.

Signed-off-by: Greg Wilkins <gregw@webtide.com>

Code cleanups. Signed-off-by: Simone Bordet <simone.bordet@gmail.com>

sbordet · 2017-12-28T16:24:46Z

@gregw I reverted some of your changes about formatting, as you did the wrong fix.
Cleaned up code as well, removing forgotten imports, redundant variable declarations and initializations, etc.
Good to be merged, you can squash the commits.

gregw · 2018-01-02T09:58:04Z

@sbordet your commit is wrong, as I explained before, you cannot call super.dump and dump as it results in badly formatted output like:

 |   |   += org.eclipse.jetty.io.ManagedSelector@5123a213 id=2 keys=1 selected=0 actions=0 - STARTED
 |   |   |   += EatWhatYouKill@52525845/SelectorProducer@3b94d659/PRODUCING/ReservedThreadExecutor@2db7a79b{s=1/8,p=0}@SelectorManager@ServerConnector@6a1aab78{HTTP/1.1,[http/1.1]}{localhost:8080}[nb=2,c=0,e=0]@2018-01-02T10:54:20.820985+01:00 - STARTED
 |   |   |       +- SelectorProducer@3b94d659
 |   |   |   +- actions @ 2018-01-02T10:54:20.821208+01:00
 |   |   |   +- keys @ 2018-01-02T10:54:20.821747+01:00
 |   |   |       +- sun.nio.ch.EPollSelectorImpl@79cc5584 keys=1
 |   |   |       +- SelectionKey@38f15fbf{i=1}->SocketChannelEndPoint@391a331f{/127.0.0.1:52376<->/127.0.0.1:8080,OPEN,fill=FI,flush=-,to=7217/30000}{io=1/1,kio=1,kro=0}->HttpConnection@7a41ab5b[p=HttpParser{s=START,0 of -1},g=HttpGenerator@487f0f0b{s=START}]=>HttpChannelOverHttp@218af79{r=0,c=false,a=IDLE,uri=null}

There needs to be a single call to dump, which was the original intent of my fix. I will revert your commit and we can hangout so you can explain what you are trying to fix???

This reverts commit 4febaf1.

Signed-off-by: Greg Wilkins <gregw@webtide.com>

gregw requested a review from sbordet December 14, 2017 22:29

gregw self-assigned this Dec 14, 2017

gregw added Enhancement Sponsored This issue affects a user with a commercial support agreement labels Dec 14, 2017

sbordet requested changes Dec 19, 2017

View reviewed changes

moved utility timestamp format method to Log

648ca4e

Signed-off-by: Greg Wilkins <gregw@webtide.com>

sbordet requested changes Dec 20, 2017

View reviewed changes

gregw added 2 commits December 20, 2017 12:13

Merge branch 'jetty-9.4.x' into jetty-9.4.x-1970-dump-improvements

ffda0c7

updates after review

d45d8e0

Signed-off-by: Greg Wilkins <gregw@webtide.com>

gregw mentioned this pull request Dec 27, 2017

Jetty 9.4.x #1970 lost selector #2023

Closed

sbordet requested changes Dec 27, 2017

View reviewed changes

gregw and others added 2 commits December 28, 2017 10:36

changes after review

ee133e5

Signed-off-by: Greg Wilkins <gregw@webtide.com>

Issue #1970 - ManagedSelector dump improvements.

4febaf1

Code cleanups. Signed-off-by: Simone Bordet <simone.bordet@gmail.com>

gregw added 2 commits January 2, 2018 11:07

Revert "Issue #1970 - ManagedSelector dump improvements."

f8bc8a6

This reverts commit 4febaf1.

Fixed imports and other review feedback

75e0d85

Signed-off-by: Greg Wilkins <gregw@webtide.com>

gregw merged commit 54c55b6 into jetty-9.4.x Jan 2, 2018

gregw deleted the jetty-9.4.x-1970-dump-improvements branch January 8, 2018 15:18

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ManagedSelector dump improvements from #1970 #2062

ManagedSelector dump improvements from #1970 #2062

gregw commented Dec 14, 2017

sbordet Dec 19, 2017

gregw Dec 20, 2017

sbordet Dec 20, 2017

sbordet Dec 19, 2017

gregw Dec 20, 2017

sbordet Dec 20, 2017

gregw Dec 20, 2017

sbordet Dec 20, 2017 •

edited

Loading

sbordet Dec 19, 2017

gregw Dec 20, 2017

sbordet Dec 20, 2017

sbordet Dec 19, 2017

sbordet Dec 19, 2017

gregw Dec 20, 2017

sbordet Dec 20, 2017

sbordet Dec 19, 2017

gregw Dec 20, 2017

sbordet Dec 20, 2017

gregw Dec 20, 2017

sbordet Dec 19, 2017

gregw Dec 20, 2017

sbordet Dec 20, 2017

gregw Dec 20, 2017

sbordet Dec 19, 2017

gregw Dec 20, 2017

sbordet Dec 20, 2017

sbordet Dec 20, 2017

gregw commented Dec 27, 2017

sbordet Dec 27, 2017

sbordet Dec 27, 2017

sbordet Dec 27, 2017

sbordet commented Dec 27, 2017

sbordet commented Dec 28, 2017

gregw commented Jan 2, 2018

ManagedSelector dump improvements from #1970 #2062

ManagedSelector dump improvements from #1970 #2062

Conversation

gregw commented Dec 14, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sbordet Dec 20, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gregw commented Dec 27, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sbordet commented Dec 27, 2017

sbordet commented Dec 28, 2017

gregw commented Jan 2, 2018

sbordet Dec 20, 2017 •

edited

Loading