Skip to content

Commit

Permalink
ManagedSelector dump improvements from #1970
Browse files Browse the repository at this point in the history 
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>
  • Loading branch information
@gregw
gregw committed Dec 14, 2017
1 parent 48a4db6 commit 402d869
Show file tree
Hide file tree
Showing 3 changed files with 96 additions and 47 deletions.
65 changes: 40 additions & 25 deletions jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,11 +30,12 @@
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collections;
import java.util.Deque;
import java.util.Iterator;
import java.util.List;
import java.util.Queue;
import java.util.Set;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.Exchanger;
import java.util.concurrent.Executor;
import java.util.concurrent.RejectedExecutionException;
import java.util.concurrent.TimeUnit;
Expand All @@ -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;
import org.eclipse.jetty.util.thread.ExecutionStrategy;
import org.eclipse.jetty.util.thread.Invocable;
import org.eclipse.jetty.util.thread.Locker;
Expand All @@ -64,7 +66,7 @@ public class ManagedSelector extends ContainerLifeCycle implements Dumpable

private final Locker _locker = new Locker();
private boolean _selecting = false;
private final Queue<Runnable> _actions = new ArrayDeque<>();
private final Deque<Runnable> _actions = new ArrayDeque<>();
private final SelectorManager _selectorManager;
private final int _id;
private final ExecutionStrategy _strategy;
Expand Down Expand Up @@ -244,20 +246,31 @@ private int getActionSize()
@Override
public void dump(Appendable out, String indent) throws IOException
{
super.dump(out, indent);
Selector selector = _selector;
List<String> keys = null;
List<Runnable> actions = null;
if (selector != null && selector.isOpen())
{
List<Runnable> actions;
DumpKeys dump = new DumpKeys();
String actionsAt;
try (Locker.Lock lock = _locker.lock())
{
actionsAt = StdErrLog.timestamp(System.currentTimeMillis(),TimeUnit.MILLISECONDS);
actions = new ArrayList<>(_actions);
_actions.addFirst(dump);
_selecting = false;
}
List<Object> keys = new ArrayList<>(selector.keys().size());
DumpKeys dumpKeys = new DumpKeys(keys);
submit(dumpKeys);
dumpKeys.await(5, TimeUnit.SECONDS);
dump(out, indent, Arrays.asList(new DumpableCollection("keys", keys), new DumpableCollection("actions", actions)));
_selector.wakeup();
keys = dump.get(5, TimeUnit.SECONDS);
String keysAt = StdErrLog.timestamp(System.currentTimeMillis(),TimeUnit.MILLISECONDS);
if (keys==null)
keys = Collections.singletonList("NO DUMP RESPONSE");
dumpBeans(out, indent, Arrays.asList(new DumpableCollection("actions @ "+actionsAt, actions),
new DumpableCollection("keys @ "+keysAt, keys) ));
}
else
{
dumpBeans(out,indent);
}
}

Expand Down Expand Up @@ -495,46 +508,48 @@ public String toString()

private class DumpKeys extends Invocable.NonBlocking
{
private final CountDownLatch latch = new CountDownLatch(1);
private final List<Object> _dumps;

private DumpKeys(List<Object> dumps)
{
this._dumps = dumps;
}

private final Exchanger<List<String>> _dump = new Exchanger<>();

@Override
public void run()
{
Selector selector = _selector;
List<String> list = new ArrayList<>(selector.keys().size()+1);
if (selector != null && selector.isOpen())
{
Set<SelectionKey> keys = selector.keys();
_dumps.add(selector + " keys=" + keys.size());
list.add(selector + " keys=" + keys.size());
for (SelectionKey key : keys)
{
try
{
_dumps.add(String.format("SelectionKey@%x{i=%d}->%s", key.hashCode(), key.interestOps(), key.attachment()));
list.add(String.format("SelectionKey@%x{i=%d}->%s", key.hashCode(), key.interestOps(), key.attachment()));
}
catch (Throwable x)
{
_dumps.add(String.format("SelectionKey@%x[%s]->%s", key.hashCode(), x, key.attachment()));
list.add(String.format("SelectionKey@%x[%s]->%s", key.hashCode(), x, key.attachment()));
}
}
}
latch.countDown();
try
{
_dump.exchange(list,500,TimeUnit.MILLISECONDS);
}
catch (Exception e)
{
LOG.ignore(e);
}
}

public boolean await(long timeout, TimeUnit unit)
public List<String> get(long timeout, TimeUnit unit)
{
try
{
return latch.await(timeout, unit);
return _dump.exchange(null,timeout, unit);
}
catch (InterruptedException x)
catch (Exception x)
{
return false;
return null;
}
}
}
Expand Down
21 changes: 21 additions & 0 deletions jetty-util/src/main/java/org/eclipse/jetty/util/component/DumpableCollection.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@
package org.eclipse.jetty.util.component;

import java.io.IOException;
import java.util.Arrays;
import java.util.Collection;

import org.eclipse.jetty.util.component.ContainerLifeCycle;
Expand All @@ -34,6 +35,12 @@ public DumpableCollection(String name,Collection<?> collection)
_name=name;
_collection=collection;
}

public DumpableCollection(String name,Object... item)
{
_name=name;
_collection=Arrays.asList(item);
}

@Override
public String dump()
Expand All @@ -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
{
public DumpableThread(String prefix,Thread thread)
{
super(prefix+thread.getId()+"-"+thread.getName()+":"+thread.getState()+"="+thread.getPriority(),
Arrays.asList(thread.getStackTrace()));
}

public DumpableThread(Thread thread)
{
this("",thread);
}
}
}
57 changes: 35 additions & 22 deletions jetty-util/src/main/java/org/eclipse/jetty/util/log/StdErrLog.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@
import java.io.PrintStream;
import java.security.AccessControlException;
import java.util.Properties;
import java.util.concurrent.TimeUnit;

import org.eclipse.jetty.util.DateCache;
import org.eclipse.jetty.util.annotation.ManagedAttribute;
Expand Down Expand Up @@ -95,7 +96,7 @@ public class StdErrLog extends AbstractLogger
private static final String EOL = System.getProperty("line.separator");
// Do not change output format lightly, people rely on this output format now.
private static int __tagpad = Integer.parseInt(Log.__props.getProperty("org.eclipse.jetty.util.log.StdErrLog.TAG_PAD","0"));
private static DateCache _dateCache;
private static DateCache __dateCache;

private final static boolean __source = Boolean.parseBoolean(Log.__props.getProperty("org.eclipse.jetty.util.log.SOURCE",
Log.__props.getProperty("org.eclipse.jetty.util.log.stderr.SOURCE","false")));
Expand All @@ -118,7 +119,7 @@ public class StdErrLog extends AbstractLogger

try
{
_dateCache = new DateCache("yyyy-MM-dd HH:mm:ss");
__dateCache = new DateCache("yyyy-MM-dd HH:mm:ss");
}
catch (Exception x)
{
Expand All @@ -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)
{
long ms = units.toMillis(time);
StringBuilder buffer = new StringBuilder();
timestamp(buffer,__dateCache.formatNow(ms),(int)(ms%1000));
return buffer.toString();
}

private static void timestamp(StringBuilder buffer, String date, int ms)
{
buffer.append(date);
if (ms > 99)
{
buffer.append('.');
}
else if (ms > 9)
{
buffer.append(".0");
}
else
{
buffer.append(".00");
}
buffer.append(ms);
}


public static int getLoggingLevel(Properties props,String name)
{
Expand Down Expand Up @@ -434,13 +461,13 @@ public void debug(String msg, Throwable thrown)

private void format(StringBuilder buffer, String level, String msg, Object... args)
{
buffer.setLength(0);
long now = System.currentTimeMillis();
int ms=(int)(now%1000);
String d = _dateCache.formatNow(now);
tag(buffer,d,ms,level);
timestamp(buffer,__dateCache.formatNow(now),(int)(now%1000));
tag(buffer,level);
format(buffer,msg,args);
}

private void format(StringBuilder buffer, String level, String msg, Throwable thrown)
{
format(buffer,level,msg);
Expand All @@ -454,23 +481,9 @@ private void format(StringBuilder buffer, String level, String msg, Throwable th
}
}

private void tag(StringBuilder buffer, String d, int ms, String tag)
private void tag(StringBuilder buffer, String tag)
{
buffer.setLength(0);
buffer.append(d);
if (ms > 99)
{
buffer.append('.');
}
else if (ms > 9)
{
buffer.append(".0");
}
else
{
buffer.append(".00");
}
buffer.append(ms).append(tag);
buffer.append(tag);

String name=_printLongNames?_name:_abbrevname;
String tname=Thread.currentThread().getName();
Expand Down

0 comments on commit 402d869

Please sign in to comment.