Hmm, windows xp console screwing my performance?

Performance Tuning
#1

Hi

I’ve been working on a little piece of my code, trying to solve some performance issues I was getting. The piece of code updates a list of collisions between objects, and then goes through the objects updating their velocities from the collision, then loops round every object and updates it’s location based on velocity and acceleration.

Updating the collision lists gets run often, and as part of it, it gets a list of all object pairs to check for collisions, then calls the method that does the check for that object pair.

I was seeing issues where the collision update was normally taking around 3ms when I had 200 objects in the scene, but would sometimes pike to as much as 60+ms. No good when I am trying to reach a minimum of 30fps, and I’ve not got the lowest spec hardware, so on my hardware I should be approaching 100 or more. The collisions are only updated if a certain amount of time has passed, so if it’s set at 25ms updates, it will not update until 25ms since the last one, and then will do 1 update, which will effect that frames rendering time. 60ms in the middle of that is unplayable.

Having tried netbeans profiler, I couldn’t find any indication as to what the spike was, so I dumped a large amount of debug to see what methods were taking how long on the laggy frames.

I couldn’t see what was causing it even with this extra debug, all the methods seemed to increase in time when I hit the performance drop.

I happened to try the isolated test on a linux box and there was no issue. I tried a few other vm versions on windows to see if it was a jvm issue. If the problem didn’t exist on linux, it suggested it was not my code. I then thought about getting a webstart version running so that I could ask for testers to see if it was my machine. I replaced System.out with a JTextArea in a noddy application and the performance drop again vanished!. Most odd.

I normally leave my machine on 24x7, but we had a power cut last night, so it got rebooted. This evening, out of curiosity I ran the old application, and all was fine, even dumping to the console. In disbelief, I ran it again, and it was screwed. I closed the console, started a new one, and ran it again, all was fine.

It seems that writing to the console in win xp after the first couple of dozen lines of text, starts to seriusly effect performance when you are worried about methods that are called thousands of times a second.

Has anyone else seen this?. Just trying to see if I am missing something else, or if it really not my code, and just not writing to the console will solve my issues.

Thanks

Endolf

#2

It’s a known issue that console output really screws performance.

For that reason (well, also for that reason) I added some quake-ish console to my framework, which shows up to X lines for Y seconds even when the console is hidden. This allows me to flood out some debug garbage w/o affecting performance much.

#3

System.out printing doesn’t make sense if you intend to have a complete GUI logged, because of synch operations on the stdout that cannot be overriden at any level of your code. That’s why I did on my own to build a proprietery console system with a drawNewLine(String) ti implement Console logging. I was wrting the Console PrintStream impl in my own Java Class so that I could use System.setOut(PrintStream) which works well with JSwing but doesn’t if I try to draw on Graphics. So I have got an implemented LogArea in JSwing but I couldn’t get to draw on Graphics with the same framework… It brings my app to a dead-lock that it seems impossible to void.
Maybe you can have a look to both Java Classes, the first one is a JSwing component ScrollingArea the second one is an implementation of a Sprite extended to a Real-Time Console Area:

/** This classe extends JScrollPane to serve logging purposals in one Swing application.
 */
public class LogArea extends ActiveScrollPane implements InputLogListener, Appendable {
    final JTextArea text;
    Set<OutputLogListener> output = Collections.synchronizedSet(new HashSet<OutputLogListener>());
    /** log stack */
    volatile Stack log;
    /** default text field */
    String defaultText;
    
    private final static int PRINT_ERROR = 0;

    private boolean toStdout = true;

    private boolean fromStdout = false;
    JMenu pMenu;
    /** Constructs a new LogArea */
    public LogArea() {
        this("");
    }
    
    /** Constructs a new LogArea with text initially displayed
     * @param defaultText is saved in defaultText field*/
    public LogArea(String defaultText) {
        super();
        this.defaultText = defaultText;
        log = new Stack();
        text = new JTextArea();
        text.setDoubleBuffered(true);
        text.setLineWrap(true);
        text.setText(defaultText);
        add(text);
        pMenu = new JMenu("log stack");
        pMenu.add(new AbstractAction("log stdout") { public void actionPerformed(ActionEvent e) {
            setLogStdOutEnabled(!LogArea.this.fromStdout);
        }});
        pMenu.add(new AbstractAction("save to file...") { public void actionPerformed(ActionEvent e) {
            FileChooserPane fcp = new FileChooserPane(null, ".");
            fcp.setMultiSelectionEnabled(false);
            File[] f = fcp.getFile();
            try {
                if(f != null)
                    saveToDisk(f[0].getPath());
            } catch (FileNotFoundException ex) {
                ex.printStackTrace();
            } catch (IOException ex) {
                ex.printStackTrace();
            }
        }});
        pMenu.add(new AbstractAction("clear") { public void actionPerformed(ActionEvent e) {
            clearLog();
        }});
        pMenu.setRequestFocusEnabled(true);
        text.add(pMenu);
        setWheelScrollingEnabled(true);
        
        validate();
    }
    
    /** Returns the text in log
     * @return text*/
    private String getText() {
        return text.getText();
    }
    /** Attempts to add new data to log.
     *@param c character to append
     *@return Appendable interface, this object
     *@see java.util.Formatter */
    public Appendable append(char c) {
        log.push(String.valueOf(c));
        text.append(String.valueOf(c));
        text.setCaretPosition(text.getText().length() - 1);
        if(toStdout)
            System.out.print(c);
        update();
        return this;
    }
    /** Attempts to add new data sequence to log.
     *@param csq Character sequence to append
     *@return Appendable interface, this object
     **@see java.util.Formatter*/
    public Appendable append(CharSequence csq) {
        log.push(csq.toString());
        text.append(csq.toString());
        text.setCaretPosition(text.getText().length() - 1);
        if(toStdout)
            System.out.println(csq);
        update();
        return this;
    }
    /** Attemps to add new data to log from start to end index of that sequence.
     *@param csq Character sequence
     *@param start starting index
     *@param end end index
     *@see java.util.Formatter*/
    public Appendable append(CharSequence csq, int start, int end) {
        String s = csq.toString().substring(start,end);
        log.push(s);
        text.append(s);
        text.setCaretPosition(text.getText().length() - 1);
        if(toStdout)
            System.out.println(s);
        update();
        return this;
    }
    /** Logs new posted message to this LogArea.
     * @param message the message posted*/
    public void newLogPosted(String message) {
        pushNewLog(message);
        super.setScrollPosition(super.getHAdjustable().getMaximum(), super.getVAdjustable().getMaximum());
    }
    /** Clears the text but the stack memory keeps unchanged.
     */
    public void clearLog() {
        text.setText(defaultText);
    }
    /** Adds a new Log line to this LogArea.
     *@param newLog log text
     *@return the logged text
     */
    public String pushNewLog(String newLog) {
        log.push(newLog += " -log- ");
        append(newLog);
        return newLog;
    }
    /** Pops off the last log message.
     *@return the log popped off
     *@see java.util.Vector*/
    public String popLastLog() {
        return (String)log.pop();
    }
    
    /** Updates the view of this LogArea and resizes it too.
     **/
    public void update() {
        int pty = Thread.currentThread().getPriority();
        Thread.currentThread().setPriority(Thread.MAX_PRIORITY);
        super.update(getGraphics());
        Thread.currentThread().setPriority(pty);
    }
    
    /** returns a new PrintStream to print on loggin' stack
     @param l Output listener to the printStream (@see OutputLogListener)
     @return new PrintStream instance ready to be used as an @see Output*/
    public PrintStream getPrintStream(OutputLogListener l) {
        addOutputLogListener(l);
        final PipedOutputStream pipedOutputStream = new PipedOutputStream();
        Thread t = new Thread(new Runnable() { public void run() {
            PipedInputStream pis = null;
            try {
                pis = new PipedInputStream(pipedOutputStream);
                byte[] b = new byte[32];
                while(pis.read(b) != -1)
                    newLogPosted(new String(b));
            } catch (IOException ex) {
                ex.printStackTrace();
                notifyOutput(PRINT_ERROR, ex);
                try {
                    pipedOutputStream.flush();
                } catch (IOException ex2) {
                    ex2.printStackTrace();
                }
            }
        }}, "T-logPrintStream");
        t.setPriority(Thread.MAX_PRIORITY - 1);
        t.start();
        return new PrintStream(pipedOutputStream);
    }
    
    /** stores log to a file on disk */
    public void saveToDisk(String filename) throws FileNotFoundException, IOException {
        RandomAccessFile raf = new RandomAccessFile(filename, "rws");
        raf.seek(raf.length() - 1);
        raf.writeUTF(this.text.getText());
        raf.close();
    }
    
    /***/
    public JMenu getActionMenu() {
        return pMenu;
    }
    
    /***/
    public void setStdOutEnabled(boolean b) {
        toStdout = b;        
        
    }
    /***/
    public void setLogStdOutEnabled(boolean b) {
        fromStdout = b;
        System.setOut(getPrintStream(new OutputLogListener() {
            public void printStreamError(IOException e) {
                setLogStdOutEnabled(LogArea.this.fromStdout);
            }
        }));
    }
    
    /***/
    public void addOutputLogListener(OutputLogListener l) {
        output.add(l);
    }
    
    /***/
    public void removeLogListener(OutputLogListener l) {
        output.remove(l);
    }
    /***/
    private void notifyOutput(int event, IOException e) {
        synchronized(output) {
            switch(event) {
                case PRINT_ERROR:
                    for(Iterator<OutputLogListener> i = output.iterator(); i.hasNext();)
                        i.next().printStreamError(e);
                    break;
                default:
            }
        }
    }
}

following code in next post : GUICharacterOutput

#4

following the previous post:

/*
 * GUICharacterOutput.java
 *
 * Created on 22 novembre 2006, 23:33
 *
 * To change this template, choose Tools | Template Manager
 * and open the template in the editor.
 */

/**
 *
 * @author website
 */
public class GUICharacterOutput extends Sprite implements InputLogListener, Appendable{
    public final static int TOP = 0;
    public final static int BOTTOM = 1;
    public final static int RIGHT = 2;
    public final static int LEFT = 3;
    public final static int CENTER = 4;
    private int valign = TOP;
    private int align = RIGHT;
    private float alpha = 0.8f;
    private StringBuffer buffer = new StringBuffer();
    private int lastOutputRowPX = 0;
    private int outputRowPX_pad = 5;
    private int outputColPX_pad = 10;
    private int lastOutputColPX = 0;
    private final static int PRINT_ERROR = 0;
    private Component streamingComp;
    private boolean toStdout = false;
    private boolean fromStdout = false;
    private Set<OutputLogListener> output = Collections.synchronizedSet(new HashSet<OutputLogListener>());
    
    /** Creates a new instance of GUICharacterOutput */
    public GUICharacterOutput(Dimension size) {
        super(createBufferedImage(size), "image/png", size);
    }
    
    /***/
    public void setStdOutEnabled(boolean b) {
        toStdout = b;
        
    }
    
    /***/
    public void setLogStdOutEnabled(boolean b) {
        fromStdout = b;
        System.setOut(getPrintStream(new OutputLogListener() {
            public void printStreamError(IOException e) {
                setLogStdOutEnabled(GUICharacterOutput.this.fromStdout);
            }
        }));
    }
    
    /***/
    public void addOutputLogListener(OutputLogListener l) {
        output.add(l);
    }
    
    /***/
    public void removeLogListener(OutputLogListener l) {
        output.remove(l);
    }
    /***/
    private void notifyOutput(int event, IOException e) {
        synchronized(output) {
            switch(event) {
                case PRINT_ERROR:
                    for(Iterator<OutputLogListener> i = output.iterator(); i.hasNext();)
                        i.next().printStreamError(e);
                    break;
                default:
            }
        }
    }
    
    /***/
    private void drawNewLine(String message, Graphics2D g2) {
        Dimension messageDim = RenderingScene.toGraphicalMetrics(message, g2);
        if((lastOutputRowPX + outputRowPX_pad + messageDim.height) >= size.height) {
            lastOutputRowPX = 0;
            g2.clearRect(0, 0, size.width, size.height);
        }
        Point pos = new Point(0, 0);
        switch(align) {
            case CENTER:
                pos.x = (int)(g2.getClipBounds().width/2 - messageDim.width/2);
                break;
            case RIGHT:
                pos.x = (int)(g2.getClipBounds().width - messageDim.width - outputColPX_pad);
                break;
            case LEFT:
                pos.x = outputColPX_pad;
                break;
            default :
                pos.x = 0;
        }
        switch(valign) {
            case CENTER:
                pos.y = (int)(g2.getClipBounds().height/2 - messageDim.height/2);
                break;
            case TOP:
                pos.y = outputRowPX_pad + messageDim.height/2;
                break;
            case BOTTOM:
                pos.y = (int)(g2.getClipBounds().height - messageDim.height - outputRowPX_pad);
                break;
            default:
                pos.y = 0;
        }
        
        g2.drawString(message, pos.x, pos.y += lastOutputRowPX);
        lastOutputRowPX = pos.y;
    }
    
    /** returns a new PrintStream to print on loggin' stack
     * @param l Output listener to the printStream (@see OutputLogListener)
     * @return new PrintStream instance ready to be used as an @see Output*/
    public PrintStream getPrintStream(OutputLogListener l) {
        addOutputLogListener(l);
        final PipedOutputStream pipedOutputStream = new PipedOutputStream();
        Thread t = new Thread(new Runnable() { public void run() {
            PipedInputStream pis = null;
            try {
                pis = new PipedInputStream(pipedOutputStream);
                byte[] b = new byte[32];
                while(pis.read(b) != -1)
                    newLogPosted(new String(b));
            } catch (IOException ex) {
                ex.printStackTrace();
                notifyOutput(PRINT_ERROR, ex);
                try {
                    pipedOutputStream.flush();
                } catch (IOException ex2) {
                    ex2.printStackTrace();
                }
            }
        }}, "T-logPrintStream");
        t.setPriority(Thread.MAX_PRIORITY - 1);
        t.start();
        return new PrintStream(pipedOutputStream);
    }
    
    public void newLogPosted(String message) {
        GraphicsJAI g2 = getGraphics();
        drawNewLine(message, g2);
        buffer.append("\n\rGUIConsole - " + message);
    }
    
    public Appendable append(CharSequence charSequence) throws IOException {
        return buffer.append(charSequence);
    }
    
    public Appendable append(CharSequence charSequence, int i, int i0) throws IOException {
        return buffer.append(charSequence, i, i0);
    }
    
    public Appendable append(char c) throws IOException {
        return buffer.append(c);
    }
    
    public void setAlpha(float alpha) {
        this.alpha = alpha;
    }
    
    public void setAlign(int align) {
        this.align = align;
    }
    
    public void setValign(int valign) {
        this.valign = valign;
    }
    
    public void clearContents() {
        buffer = new StringBuffer();
        getGraphics().clearRect(0, 0, size.width, size.height);
    }
    
    public void draw(Graphics2D g2) {
        Composite cps = g2.getComposite();
        g2.setComposite(AlphaComposite.getInstance(AlphaComposite.SRC_OVER, alpha));
        /*char[] line = new char[(int)Math.floor(size.width/g2.getFontMetrics().getMaxAdvance())];
        int readChars = 0;
        int bL = buffer.length();
        while(readChars < bL - line.length) {
            try{
                buffer.getChars(readChars, line.length, line, 0);
                drawNewLine(new String(line), g2);
            } catch(IndexOutOfBoundsException e) {
                drawNewLine(new String(line), g2);
            } finally {
                readChars += line.length;
            }
        }
        buffer.delete(0, readChars);*/
        super.draw(g2);
        g2.setComposite(cps);
    }
}
#5

Sorry, I might be confused here, but can’t you do a System.setOut(InputStream); ? That reroutes whatever anyone writes to System.out to your inputstream…

DP :slight_smile:

#6

System.setOut(new PrintStream(new ConsoleOutputStream()));

:wink:

#7

the code posted beyond works fine, but if you intend to eventually “switch on/off” you may face a synch’ issue with the ConsoleListener. Thus, I modified both message post and message graphical drawing with synch’ functions. It might look like:

GUIConsoleOutput implements InputLogListener { 
Stack<String> buffer = new Stack<String>();
void newlogposted(String s) {
    synchronized(this) {
        try{ wait(); } catch(InterruptedException e) {}
        postBuffer(s);
   }
}

while the callback to draw system notifies:

private synchronized void draw(Graphics g, Component c) {
    while(!buffer.empty())
           drawNewLine(buffer.pop());
    notify();
}
}

;D

#8

Always one step ahead of me there onyx :-*