Why is Document.insertString()'s runtime not constant-time?

Question

I am working on creating a logger to show output as part of a larger Java swing GUI. Unfortunately I was experiencing a slowdown after adding it. I have traced the problem to repeated calls of Document.insertString().

I made a test which shows this slowdown:

LogPanel.java

public class LogPanel extends JPanel{
    private static final SimpleDateFormat df = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
    private JEditorPane textPane;
    private static int numTextRows = 50;
    private SimpleAttributeSet keyWord;
    private Document document;

   public LogPanel() {
        super(new BorderLayout());
        add(makePanel(), BorderLayout.CENTER);
    }

    private Component makePanel() {
        // Just a text area that grows and can be scrolled.
        textPane = new JTextPane();
        document = textPane.getDocument();
        keyWord = new SimpleAttributeSet();
        StyleConstants.setForeground(keyWord, Color.BLACK);

        //textArea.setRows(numTextRows);
        textPane.setEditable(false);
        textPane.setFont(new Font("monospaced", Font.PLAIN, 12));

        DefaultCaret caret = (DefaultCaret) textPane.getCaret();
        caret.setUpdatePolicy(DefaultCaret.ALWAYS_UPDATE);

        //Wrap the textPane in a JPanel with BorderLayout so that the text does not wrap
        JPanel textPaneWrapper = new JPanel();
        textPaneWrapper.setLayout(new BorderLayout());
        textPaneWrapper.add(textPane);

        JScrollPane areaScrollPane = new JScrollPane(textPaneWrapper);
        areaScrollPane.getVerticalScrollBar().setUnitIncrement(20);
        //JScrollPane areaScrollPane = new JScrollPane(textPane);
        areaScrollPane.setVerticalScrollBarPolicy(JScrollPane.VERTICAL_SCROLLBAR_ALWAYS);
        areaScrollPane.setHorizontalScrollBarPolicy(JScrollPane.HORIZONTAL_SCROLLBAR_AS_NEEDED);
        areaScrollPane.setPreferredSize(new Dimension(250, 250));
//        builder.add(areaScrollPane, cc.xywh(1, 3, 3, 1));

        StyleConstants.setBackground(keyWord, areaScrollPane.getBackground());
        textPane.setBackground(areaScrollPane.getBackground());

        return areaScrollPane;
    }

    public void appendResult(final String action, final String result, final Color color) {
        Date now = new Date();
        String strDate = df.format(now);
        String paddedAction = String.format("%-19s", action);
        StyleConstants.setForeground(keyWord, color);

        try {
            document.insertString(document.getLength(), strDate + "   " + paddedAction + "   " + result + "\n", keyWord);
        } catch (BadLocationException e) {
            throw new RuntimeException(e);
        } 

        if(!textPane.hasFocus()) {
            textPane.setCaretPosition(document.getLength());
        }
    }

    public void appendResult(String action, String result) {
        appendResult(action, result, Color.BLACK);
    }
}

LogTester.Java

public class LogTester extends JFrame{
    private LogPanel logPanel;
    private JButton pushMe;

    public LogTester(){
        setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
        setLayout(new GridBagLayout());

        logPanel = new LogPanel();
        this.add(logPanel);

        pushMe= new JButton("Press Me");
        LogTester self=this;
        pushMe.addActionListener(new ActionListener(){
            public void actionPerformed(ActionEvent e) {
                self.addLotsOfStuff();
            }
        });
        this.add(pushMe);

        this.pack();
        this.setVisible(true);

    }

    public void addLotsOfStuff(){
        for(int i=0; i<1000; i+=1){
            long start=System.currentTimeMillis();
            for(int j=0; j<1000; j+=1){
                String str="This is a very long peice of text designed to test the capabilites of our log panel. Move along, nothing to see here.";
                logPanel.appendResult("HERP",str);
            }
            long end=System.currentTimeMillis();
            System.out.println(end-start);
        }
    }

    public static void main(String args[]){
        LogTester test=new LogTester();
    }
}

The program above attempts to write a large number of lines to a JTextPane, which utilizes Document.insertString(). The results of this program are concerning:

For some reason, each call to this function increases the runtime of the next call: It looks linear or even mildly exponential. This might imply that all the previous contents of the document are being copied on each insert, rather than the new string being appended (in some sort of linked list fashion)

Unlike Java GUI freezing because of insertString method? I am primarily concerned with the increasing runtime of the function, not the idle time of the application. Adding threading will not help if each individual call gets very slow.

Unlike Limit JTextPane space usage I am not concerned with large memory usage. If the document is large, it will use a large amount of memory. I just don't understand why that would affect the runtime of inserting more information to the Document.

Perhaps the slowdown can be attributed to this caret position memory leak?

What parts of JTextPane or Document would I have to override in order to achieve a constant time insertString()?

Answer 1

Growing arrays is nearly linear, but not actually linear.

Once you exceed the size of the level 1 cache line, you use another until:

• There are no free cache lines, so you have to evict an existing line cache, populating it from a portion of a level 2 cache line.
• There are no free level 2 cache lines, so you have to evict one of those, populating it from a (Typically) general RAM reqeust.
• Your general RAM request is too large to fit into one request, and the group of requested pages can not be co-fetched due to their count or memory chip locations.

This means that, even for linear operations, really small stuff runs much, much faster than the same linear algorithm dealing with a much larger amount of data.

So when deciding on if an algorithm is O(n) or otherwise, it's important to remember that such a decision is based on a fundamental understanding of the expectations of your computing model. Big-O notation assumes that all RAM fetches are equal in time, and computations (operations) are also equal in time. Under such constraints, comparing the count of the operations to the amount of data still makes sense; but, assuming the wall clock time is exact doesn't.