EDT scheint zu blocken wegen Dateioperation in anderem Thread

[Illuvatar]

Hi Leute,

ich bin grade dabei mir ein kleines eigenes TreeModel für Ordnerstrukturen / Dateien zu basteln. Der Grund ist: Zumindest bei mir gibt es ein paar Ordner, bei denen File#listFiles() schon mal ein paar Sekunden dauern kann - zum Beispiel "Netzwerk" oder das (sowieso leere, aber trotzdem noch angeschlossene) Diskettenlaufwerk A.
Mein Plan war jetzt, dass das Model in einem eigenen Thread schonmal die Unterverzeichnisse vorlädt, die möglicherweise bald abgefragt werden. Und das hat jetzt sehr seltsame Effekte: das Ganze funktioniert nur sehr selten mal zufällig (d.h. normalerweise braucht es einige Zeit bis die Unterordner dargestellt werden). Und das obwohl ich mittlerweile mitprotokolliere und sämtliche Methoden meines Models üblicherweise nach (laut System.nanoTime) einem Millisekundenbruchteil zurückkehren.

Was ich aber sehe ist: ich öffne den Zweig "Computer". Da die Inhalte bereits geladen sind, sagt mein Model dem JTree sofort was alles drin ist. Gleichzeitig fängt mein Model an, die Unterordner nachzuladen - beginnend mit den Unterordnern von A:\. Und aus mysteriösen Gründen scheint das den JTree zu blockieren: erst nach ca. 1 Sekunde hab ich, dass A:\ leer ist. Dann werden plötzlich noch ein paar Methoden im Model aufgerufen und das Ergebnis wird angezeigt.

Hat irgendjemand sowas schonmal erlebt? Klingt ja wohl nach irgendwelchen Synchronisierungsproblemen Ich hab bisher nur rausfinden können, dass mein loader-Thread während dieser Sekunde via LockSupport.park -> sun.misc.Unsafe.park wohl auf irgendetwas wartet... Das heißt wohl doch nicht ohne Grund Unsafe.

----------------------------------------------
Auszug aus dem Log
Schwarz: Logging-Ausgaben aus dem TreeModel
Rot: Ausgaben des Extra-Threads
Grau: Kommentare von mir

At 12396130: Start Loading: C:\Users\Illuvatar\Desktop
0ms (start time: 12396171) for addTreeModelListener. Params: [javax.swing.JTree$TreeModelHandler@50c4fe76]
0ms (start time: 12396171) for getRoot. Params: []
0ms (start time: 12396171) for getRoot. Params: []
178ms (start time: 12396171) for isLeaf. Params: [C:\Users\Illuvatar\Desktop]
0ms (start time: 12396350) for getRoot. Params: []
0ms (start time: 12396350) for addTreeModelListener. Params: [javax.swing.plaf.basic.BasicTreeUI$Handler@72e6f7d2]
0ms (start time: 12396350) for getRoot. Params: []
0ms (start time: 12396351) for isLeaf. Params: [C:\Users\Illuvatar\Desktop]
0ms (start time: 12396371) for isLeaf. Params: [C:\Users\Illuvatar\Desktop]
0ms (start time: 12396372) for isLeaf. Params: [C:\Users\Illuvatar\Desktop]
0ms (start time: 12396372) for getChildCount. Params: [C:\Users\Illuvatar\Desktop]
At 12396372: Start Loading: Computer
[...] Hier werden noch einige Sachen zum Zeug aufm Desktop gefragt und alle Ordner auf dem Desktop werden vorgeladen. Unter anderem übrigens irgendwann, das braucht grade extrem lang:
At 12396598: Start Loading: Network
After 30136ms: Done Loading: Network
[...]

Hier wirds wirklich interessant: Jetzt klick ich
0ms (start time: 12429873) for isLeaf. Params: [Computer]
0ms (start time: 12429873) for isLeaf. Params: [Computer]
0ms (start time: 12429874) for isLeaf. Params: [Computer]
0ms (start time: 12429874) for isLeaf. Params: [Computer]
0ms (start time: 12429874) for isLeaf. Params: [Computer]
0ms (start time: 12429874) for getChildCount. Params: [Computer]
0ms (start time: 12429874) for getChild. Params: [Computer, 0]
0ms (start time: 12429874) for isLeaf. Params: [A:\]
At 12429874: Start Loading: A:\
0ms (start time: 12429875) for getChild. Params: [Computer, 1]
0ms (start time: 12429875) for isLeaf. Params: [C:\]
[...]
0ms (start time: 12429878) for getChild. Params: [Computer, 6]
0ms (start time: 12429878) for isLeaf. Params: [H:\]
Pause...
After 1105ms: Done Loading: A:\
At 12430979: Start Loading: C:\
Und jetzt erst fängt der JTree wieder an:
0ms (start time: 12430979) for isLeaf. Params: [C:\]
0ms (start time: 12430980) for isLeaf. Params: [D:\]
[...]
0ms (start time: 12430989) for isLeaf. Params: [C:\Users\Illuvatar\Desktop\LGVR0005.avi]
Und erst HIER wird das Fenster aktualisiert und die UI wird wieder bedienbar!
At 12430994: Start Loading: D:\
[...]
At 12431070: Start Loading: H:\

----------------------------------------------
Code
Edit: siehe hier

 

[Marco13]

Hm ... da könnte man jetzt viel spekulieren ... erstens, weil ich den Code und den Log jetzt nicht so 100% matchen kann, aber insbesondere, weil ich z.B. ad hoc nicht sagen könnte, wann der JTree sich erlaubt, welche Methoden aus dem Modell aufzurufen. Vielleicht versucht der JTree intern auch schon etwas, was in Richtung eines "Vorausladens" tieferer Kinder geht - dass er also, wenn man den "Computer" aufklappt, zwar sofort an die (vorgeladenen) Kinder rankommt, er aber noch eine Ebene tiefer gehen will (*rumrat* vielleicht um zu wissen, ob er neben dem Kind ein "[+]" einblenden muss oder nicht?)... Aber vermutlich könntest du an den Log-Ausgaben erkennen, wenn das so wäre?! Es wird wirklich der EDT blockiert?

 

[Illuvatar]

Hm ... da könnte man jetzt viel spekulieren ... erstens, weil ich den Code und den Log jetzt nicht so 100% matchen kann

Ok ich geb zu, das ist als Außenstehender jetzt vermutlich schwierig Vielleicht krieg ichs morgen mal hin, dass ich einen funktionierenden Code reinstell, und den Log den ich von dem Code erhalte.

Aber zu deiner Vermutung: Laut meinem Log ist das nicht so. Und ich erhalte bei jedem Aufruf einer Methode meines Models* in meinem Log die Ausgabe "0 Millisekunden". Genau in dem Zeitraum, in dem aber der andere Thread in FileSystemView#getFiles für das Diskettenlaufwerk ist, wird aber eine Sekunde lang nichts mehr in meinem Model aufgerufen.

*bis auf ganz am Anfang das isLeaf beim Desktop, da wird im Hintergrund das erst noch geladen und braucht deshalb 100-200 ms
Dann später, an der Stelle wo diese Blockade stattfindet, stimmt die Aussage aber


Edit: Hab im ersten Code oben (Zeilen 9-11, 14-18) den Log-Code wieder eingebaut... fragt mich nicht, warum ich das eigentlich rausgenommen hab. Daher stammen die roten Zeilen.
Die schwarzen Zeilen stammen von einem "LoggingTreeModel", das das eigentliche Model kapselt, und nach jedem Methodenaufruf die Zeit, den Methodenname und die Parameter ausgibt.

 

[Illuvatar]

Ok, hier also ein bisschen Code der bei mir das Problem reproduzieren kann. Da das Problem aber nicht bekannt zu sein scheint fürchte ich, das ist eine Eigenart von meinem Computer ???:L

Zum Testen: einfach ein bisschen in "langsamen" Dateien rumklicken, zum Beispiel Netzwerk oder DVD-Laufwerk oder so.
In der Ausgabe sieht man, wie weit das "Vorladen" ist. Wenn das fertig ist und man klickt irgendwo, sollte ohne Verzögerung der Ordner geöffnet werden. Das ist bei mir nicht immer so - manchmal manchmal scheint das Vorladen der Unterordner das Öffnen des eigentlichen Ordners aufzuhalten... In manchen Fällen (Diskettenlaufwerk ) ist das sogar immer so

import java.io.File;

import javax.swing.event.TreeModelListener;
import javax.swing.filechooser.FileSystemView;
import javax.swing.tree.TreeModel;
import javax.swing.tree.TreePath;

public class FileTreeModel implements TreeModel {
    private File root;
    private FileStructureLoader loader;

    public FileTreeModel(File root, FileSystemView fsv) {
        this.root = root;
        this.loader = new FileStructureLoader(fsv);
        
        loader.loadChildren(root);
    }

    @Override
    public void addTreeModelListener(TreeModelListener l) {
    }

    @Override
    public Object getChild(Object obj, int index) {
        File parent = (File) obj;
        File[] children = loader.getChildren(parent);
        File selectedChild = children[index];
        if (loader.isTraversable(selectedChild)) {
            loader.loadChildren(selectedChild);
        }
        return selectedChild;
    }

    @Override
    public int getChildCount(Object obj) {
        File parent = (File) obj;
        File[] children = loader.getChildren(parent);
        return children.length;
    }

    @Override
    public int getIndexOfChild(Object obj1, Object obj2) {
        File parent = (File) obj1;
        File child = (File) obj2;
        File[] children = loader.getChildren(parent);
        for (int i = 0; i < children.length; i++) {
            if (children[i].equals(child)) {
                return i;
            }
        }
        return -1;
    }

    @Override
    public Object getRoot() {
        return root;
    }

    @Override
    public boolean isLeaf(Object obj) {
        File file = (File) obj;
        return !loader.isTraversable(file);
    }

    @Override
    public void removeTreeModelListener(TreeModelListener l) {
    }

    @Override
    public void valueForPathChanged(TreePath path, Object newValue) {
        throw new UnsupportedOperationException();
    }
}

import java.io.File;
import java.util.HashMap;
import java.util.Map;
import java.util.concurrent.*;

import javax.swing.filechooser.FileSystemView;

class FileStructureLoader {
    private ExecutorService loader;
    private Map<File, Future<File[]>> children;
    private Map<File, Boolean> traversable;
    private FileSystemView fsv;

    public FileStructureLoader(FileSystemView fsv) {
        loader = Executors.newSingleThreadExecutor();
        children = new HashMap<File, Future<File[]>>();
        traversable = new HashMap<File, Boolean>();
        this.fsv = fsv;
    }

    public void loadChildren(final File parent) {
        if (children.get(parent) != null) {
            return;
        }
        Future<File[]> fileList = loader.submit(new Callable<File[]>() {
            public File[] call() {
                int t1 = (int) (System.nanoTime() / 1e6d);
                System.out.println("At " + t1 + ": Start Loading: " + parent);
                File[] ret = fsv.getFiles(parent, false);
                for (File f : ret) {
                    traversable.put(f, fsv.isTraversable(f));
                }
                int t2 = (int) (System.nanoTime() / 1e6d);
                if (t2 - t1 > 500) {
                    System.out.println("After " + (t2 - t1)
                            + "ms: Done Loading: " + parent);
                }
                return ret;
            }
        });
        children.put(parent, fileList);
    }

    public File[] getChildren(File parent) {
        if (!isTraversable(parent)) {
            return null;
        }
        if (children.get(parent) == null) {
            loadChildren(parent);
        }
        try {
            long t1 = System.nanoTime();
            File[] ret = children.get(parent).get();
            int i = (int) ((System.nanoTime() - t1) / 1e6d);
            System.out.println("---> " + i);
            return ret;
        } catch (ExecutionException e) {
            // no exception thrown in callable -> shouldnt happen
            throw new RuntimeException(e);
        } catch (InterruptedException e) {
            Thread.currentThread().interrupt();
            return new File[] {};
        }
    }
    
    public boolean isTraversable(File f) {
        Boolean b = traversable.get(f);
        if (b == null) {
            b = fsv.isTraversable(f);
            traversable.put(f, b);
        }
        return b;
    }
}

import java.util.Arrays;

import javax.swing.event.TreeModelListener;
import javax.swing.tree.TreeModel;
import javax.swing.tree.TreePath;

public class LoggingTreeModel implements TreeModel {
    private TreeModel model;

    public LoggingTreeModel(TreeModel model) {
        this.model = model;
    }

    private void log(String name, long t1, long t2, Object... params) {
        int ms = (int) ((t2 - t1) / 1e6d);
        int starttime = (int) (t1 / 1e6d);
        System.out.println(ms + "ms (start time: " + starttime + ") for "
                + name + ". Params: " + Arrays.toString(params));
    }

    @Override
    public void addTreeModelListener(TreeModelListener l) {
        long t1 = System.nanoTime();
        model.addTreeModelListener(l);
        log("addTreeModelListener", t1, System.nanoTime(), l);
    }

    @Override
    public Object getChild(Object parent, int index) {
        long t1 = System.nanoTime();
        Object ret = model.getChild(parent, index);
        log("getChild", t1, System.nanoTime(), parent, index);
        return ret;
    }

    @Override
    public int getChildCount(Object parent) {
        long t1 = System.nanoTime();
        int ret = model.getChildCount(parent);
        log("getChildCount", t1, System.nanoTime(), parent);
        return ret;
    }

    @Override
    public int getIndexOfChild(Object parent, Object child) {
        long t1 = System.nanoTime();
        int ret = model.getIndexOfChild(parent, child);
        log("getIndexOfChild", t1, System.nanoTime(), parent, child);
        return ret;
    }

    @Override
    public Object getRoot() {
        long t1 = System.nanoTime();
        Object ret = model.getRoot();
        log("getRoot", t1, System.nanoTime());
        return ret;
    }

    @Override
    public boolean isLeaf(Object node) {
        long t1 = System.nanoTime();
        boolean ret = model.isLeaf(node);
        log("isLeaf", t1, System.nanoTime(), node);
        return ret;
    }

    @Override
    public void removeTreeModelListener(TreeModelListener l) {
        long t1 = System.nanoTime();
        model.removeTreeModelListener(l);
        log("removeTreeModelListener", t1, System.nanoTime(), l);
    }

    @Override
    public void valueForPathChanged(TreePath path, Object newValue) {
        long t1 = System.nanoTime();
        model.valueForPathChanged(path, newValue);
        log("valueForPathChanged", t1, System.nanoTime(), path, newValue);
    }
}

import java.awt.BorderLayout;
import java.io.File;

import javax.swing.*;
import javax.swing.filechooser.FileSystemView;

public class FTMTester {
    public static void main(String[] args) {
        FileSystemView fsv = FileSystemView.getFileSystemView();
        File root = fsv.getHomeDirectory();
        FileTreeModel tm = new FileTreeModel(root, fsv);
        LoggingTreeModel log = new LoggingTreeModel(tm);
        
        JFrame mainFrame = new JFrame("File Tree Model");
        mainFrame.setLayout(new BorderLayout());
        JTree tree = new JTree(log);
        mainFrame.add(new JScrollPane(tree));

        mainFrame.setSize(450, 600);
        mainFrame.setLocationByPlatform(true);
        mainFrame.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
        mainFrame.setVisible(true);
    }
}

 

[Marco13]

Hm ... OK, jetzt nochmal das Symptom: Man macht das Programm auf, und es erscheint eine (bei mir seeehr lange) Liste mit den Dsktop-Einträgen. Dann klappt man "Arbeitsplatz" auf ... und die Laufwerke erscheinen sofort und ohne Verzögerung - und bei dir dauert das dann irgendwie länger oder ...?

Er sagt zwar dann auch
At 35105726: Start Loading: A:\
After 1021ms: Done Loading: A:\
aber das eigentliche Ausklappen der Laufwerke geht verzögerungsfrei...

 

[Illuvatar]

Ja das hab ich befürchtet... genau, bei mir klappt es erst auf, wenn "Done Loading: A:\" erschienen ist.

 

[Gast2]

Ich habe zwar kein Diskettenlaufwerk mehr, aber wenn ich z.b. "Netzwerk" aufklappe, dann dauerts bei mir auch so 3-4sek bis das aufklappt. In der Zeit kann ich dann auch keine anderen Einträge im Baum markieren.

WinXP, java 1.0.6_20, 32 Bit

 

[Marco13]

Hm.. schwierig... Ich würde jetzt spontan erstmal dem Executor genauer auf die Finger schauen. Also, mal einen Executor erstellen wie

loader = new ThreadPoolExecutor(1, 1, 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue<Runnable>())
{
    public void beforeExecute(Thread t, Runnable r) 
    { 
        super.beforeExecute(t,r);
        ...
    }
    public void afterExecute(Runnable r, Throwable t) 
    { 
        super.afterExecute(r, t);
        ...
    }
};

der äquivalent sein sollte zu einem "newSingleThreadExecutor", und mal schauen, was der in beforeExecute und afterExectute so alles erzählt... Ist zwar auch nur Stochern im Nebel, aber was zielgerichteteres fällt mir jetzt nicht ein.... :bahnhof:


EDIT: Hey, beim Netzwerk passiert das bei mir auch ... dann kann ich da nochmal schauen...:rtfm:

 

[Marco13]

Zusammengefasst scheint es, als würde der Aufruf von fileSystemView.getFiles(parent, false); den EDT blockieren. Ich hab' mich mal ein bißchen durch die sourcen von FileSystemView, ShellFolder & Co gebrowst, aber bin nicht wirklich draus schlau geworden. Es gibt einige Bug-reports die von Deadlocks mit bestimmten FileSystemViews handeln, und andeutungsweise wurde da an einigen Stellen gesagt, dass das FSV stark mit dem FileChooser verbunden wäre, nur vom EDT aus verwendet werden sollte, und irgendein "COM-Thread" und der EDT sich gegenseitig blockieren könnten weil sie irgendwo auf's gleiche Lock warten, aber nichts definitives, und vor allem nichts, was einen Schritt zur Behebung des Fehlers darstellen könnte....

 

[Illuvatar]

Ich bin mir nicht sicher, dass es am FileSystemView liegt. In meinem Original-Code verwend ich zwar FileSystemView, weil ich das im Renderer dann sowieso brauche - in dem oben geposteten Code hatte ich es nur verwendet weil ich gehofft hatte, ich könnte ein eigenes FileSystemView basteln, das dieses "langsame" Laden emuliert. Naja hat nicht geklappt, aber das Problem tritt ja "zum Glück" trotzdem auch bei euch auf.

Allerdings kriegt man das gleiche Ergebnis wie erwähnt auch mit File#listFiles. Hier nochmal der ganze Code etwas vereinfacht und ohne FileSystemView. Dass ich in der FileStructureLoader-Klasse auch die Information zwischenspeichere, ob die File-Objekte Ordner sind hat übrigens den Grund, dass auch isDirectory() bei mir oft blockt während so ein "kritisches" Verzeichnis vorgeladen wird. Mit dieser Methode die ich jetzt verwende kann ich garantieren, dass mein Model so schnell wie möglich returned:

import java.io.File;

import javax.swing.event.TreeModelListener;
import javax.swing.tree.TreeModel;
import javax.swing.tree.TreePath;

public class FileTreeModel implements TreeModel {
    private File root;
    private FileStructureLoader loader;

    public FileTreeModel(File root) {
        this.root = root;
        this.loader = new FileStructureLoader();
        
        loader.loadChildren(root);
    }

    @Override
    public void addTreeModelListener(TreeModelListener l) {
    }

    @Override
    public Object getChild(Object obj, int index) {
        File parent = (File) obj;
        File[] children = loader.getChildren(parent);
        File selectedChild = children[index];
        if (loader.isTraversable(selectedChild)) {
            loader.loadChildren(selectedChild);
        }
        return selectedChild;
    }

    @Override
    public int getChildCount(Object obj) {
        File parent = (File) obj;
        File[] children = loader.getChildren(parent);
        return children.length;
    }

    @Override
    public int getIndexOfChild(Object obj1, Object obj2) {
        File parent = (File) obj1;
        File child = (File) obj2;
        File[] children = loader.getChildren(parent);
        for (int i = 0; i < children.length; i++) {
            if (children[i].equals(child)) {
                return i;
            }
        }
        return -1;
    }

    @Override
    public Object getRoot() {
        return root;
    }

    @Override
    public boolean isLeaf(Object obj) {
        File file = (File) obj;
        return !loader.isTraversable(file);
    }

    @Override
    public void removeTreeModelListener(TreeModelListener l) {
    }

    @Override
    public void valueForPathChanged(TreePath path, Object newValue) {
        throw new UnsupportedOperationException();
    }
}

import java.io.File;
import java.util.HashMap;
import java.util.Map;
import java.util.concurrent.*;

class FileStructureLoader {
    private ExecutorService loader;
    private Map<File, Future<File[]>> children;
    private Map<File, Boolean> traversable;

    public FileStructureLoader() {
        loader = Executors.newSingleThreadExecutor();
        children = new HashMap<File, Future<File[]>>();
        traversable = new HashMap<File, Boolean>();
    }

    public void loadChildren(final File parent) {
        if (children.get(parent) != null) {
            return;
        }
        Future<File[]> fileList = loader.submit(new Callable<File[]>() {
            public File[] call() {
                int t1 = (int) (System.nanoTime() / 1e6d);
                System.out.println("At " + t1 + ": Start Loading: " + parent);
                File[] ret = parent.listFiles();
                for (File f : ret) {
                    traversable.put(f, f.isDirectory());
                }
                int t2 = (int) (System.nanoTime() / 1e6d);
                if (t2 - t1 > 500) {
                    System.out.println("After " + (t2 - t1)
                            + "ms: Done Loading: " + parent);
                }
                return ret;
            }
        });
        children.put(parent, fileList);
    }

    public File[] getChildren(File parent) {
        if (!parent.isDirectory()) {
            return null;
        }
        if (children.get(parent) == null) {
            loadChildren(parent);
        }
        try {
            return children.get(parent).get();
        } catch (ExecutionException e) {
            // no exception thrown in callable -> shouldnt happen
            throw new RuntimeException(e);
        } catch (InterruptedException e) {
            Thread.currentThread().interrupt();
            return new File[] {};
        }
    }
    
    public boolean isTraversable(File f) {
        Boolean b = traversable.get(f);
        if (b == null) {
            b = f.isDirectory();
            traversable.put(f, b);
        }
        return b;
    }
}

Am LoggingTreeModel ist nichts verändert.

import java.awt.BorderLayout;
import java.io.File;

import javax.swing.*;
import javax.swing.filechooser.FileSystemView;

public class FTMTester {
    public static void main(String[] args) {
        File root = FileSystemView.getFileSystemView().getHomeDirectory();
        FileTreeModel tm = new FileTreeModel(root);
        LoggingTreeModel log = new LoggingTreeModel(tm);
        
        JFrame mainFrame = new JFrame("File Tree Model");
        mainFrame.setLayout(new BorderLayout());
        JTree tree = new JTree(log);
        mainFrame.add(new JScrollPane(tree));

        mainFrame.setSize(450, 600);
        mainFrame.setLocationByPlatform(true);
        mainFrame.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
        mainFrame.setVisible(true);
    }
}