From 701b993dc3118dcfb602b806857e17387e0e4ff9 Mon Sep 17 00:00:00 2001 From: Nicolas Carranza Date: Fri, 1 May 2020 08:36:29 -0500 Subject: [PATCH 1/5] logging: handler levels and performance optimization The logging level is filtered by the Loggers, there is no need to restrict it at the handler level. It is also useful to let the handler level on ALL to allow specifying finer levels for specific classes using a logging file configuration. Some optimizations are made to avoid computing String.format and the stack trace. --- .../java/org/javacomp/logging/JLogger.java | 51 +++++++++++++------ 1 file changed, 36 insertions(+), 15 deletions(-) diff --git a/src/main/java/org/javacomp/logging/JLogger.java b/src/main/java/org/javacomp/logging/JLogger.java index d928c10..001cc82 100644 --- a/src/main/java/org/javacomp/logging/JLogger.java +++ b/src/main/java/org/javacomp/logging/JLogger.java @@ -18,6 +18,14 @@ public class JLogger { private static volatile boolean hasFileHandler = false; private final Logger javaLogger; + static { + // remove default logging handlers, we only support a FileHandler set through setLogFile + Logger rootLogger = Logger.getLogger(""); + for(Handler handler : rootLogger.getHandlers()) { + rootLogger.removeHandler(handler); + } + } + public static synchronized void setLogFile(String filePath) { Logger rootLogger = Logger.getLogger(""); @@ -38,9 +46,6 @@ public static synchronized void setLogFile(String filePath) { public static synchronized void setLogLevel(Level level) { Logger rootLogger = Logger.getLogger(""); rootLogger.setLevel(level); - for (Handler handler : rootLogger.getHandlers()) { - handler.setLevel(level); - } } private JLogger(String enclosingClassName) { @@ -50,14 +55,14 @@ private JLogger(String enclosingClassName) { /** Creates a {@link JLogger} and sets its tag to the name of the class that calls it. */ public static JLogger createForEnclosingClass() { StackTraceElement[] stackTrace = new Throwable().getStackTrace(); - // The top of the stack trace is this method. The one belows it is the caller class. + // The top of the stack trace is this method. The one below it is the caller class. String enclosingClassName = stackTrace[1].getClassName(); return new JLogger(enclosingClassName); } /** Logs a message at severe level. */ public void severe(String msg) { - log(Level.SEVERE, msg, null /* thrown */); + log(Level.SEVERE, msg); } /** @@ -67,7 +72,7 @@ public void severe(String msg) { * @param args arguments to be filled into {@code msgfmt} */ public void severe(String msgfmt, Object... args) { - log(Level.SEVERE, String.format(msgfmt, args), null /* thrown */); + log(Level.SEVERE, msgfmt, args); } /** @@ -78,12 +83,12 @@ public void severe(String msgfmt, Object... args) { * @param args arguments to be filled into {@code msgfmt} */ public void severe(Throwable thrown, String msgfmt, Object... args) { - log(Level.SEVERE, String.format(msgfmt, args), thrown); + log(Level.SEVERE, thrown, msgfmt, args); } /** Logs a message at warning level. */ public void warning(String msg) { - log(Level.WARNING, msg, null /* thrown */); + log(Level.WARNING, msg); } /** @@ -93,7 +98,7 @@ public void warning(String msg) { * @param args arguments to be filled into {@code msgfmt} */ public void warning(String msgfmt, Object... args) { - log(Level.WARNING, String.format(msgfmt, args), null /* thrown */); + log(Level.WARNING, msgfmt, args); } /** @@ -105,12 +110,12 @@ public void warning(String msgfmt, Object... args) { * @param args arguments to be filled into {@code msgfmt} */ public void warning(Throwable thrown, String msgfmt, Object... args) { - log(Level.WARNING, String.format(msgfmt, args), thrown); + log(Level.WARNING, thrown, msgfmt, args); } /** Logs a message at info level. */ public void info(String msg) { - log(Level.INFO, msg, null /* thrown */); + log(Level.INFO, msg); } /** @@ -120,12 +125,12 @@ public void info(String msg) { * @param args arguments to be filled into {@code msgfmt} */ public void info(String msgfmt, Object... args) { - log(Level.INFO, String.format(msgfmt, args), null /* thrown */); + log(Level.INFO, msgfmt, args); } /** Logs a message at fine level. */ public void fine(String msg) { - log(Level.FINE, msg, null /* thrown */); + log(Level.FINE, msg); } /** @@ -135,10 +140,26 @@ public void fine(String msg) { * @param args arguments to be filled into {@code msgfmt} */ public void fine(String msgfmt, Object... args) { - log(Level.FINE, String.format(msgfmt, args), null /* thrown */); + log(Level.FINE, msgfmt, args); + } + + public void log(Level level, String msgFormat, Object... msgArgs) { + log(level, null, msgFormat, msgArgs); } - private void log(Level level, String msg, @Nullable Throwable thrown) { + public void log(Level level, String msg) { + log(level, null, msg); + } + + public void log(Level level, @Nullable Throwable thrown, String msgFormat, Object... msgArgs) { + if(!javaLogger.isLoggable(level)) + return; + log(level, thrown, String.format(msgFormat, msgArgs)); + } + + public void log(Level level, @Nullable Throwable thrown, String msg) { + if(!javaLogger.isLoggable(level)) + return; LogRecord logRecord = new LogRecord(level, msg); if (thrown != null) { logRecord.setThrown(thrown); From 5dd715641efa44209e05bb94507abed55c4d9d47 Mon Sep 17 00:00:00 2001 From: Nicolas Carranza Date: Fri, 1 May 2020 08:55:55 -0500 Subject: [PATCH 2/5] Add fine logging messages for debugging --- src/main/java/org/javacomp/completion/Completor.java | 4 ++++ .../org/javacomp/completion/ContentWithLineMap.java | 2 ++ src/main/java/org/javacomp/file/FileWatcher.java | 5 +++++ src/main/java/org/javacomp/model/PackageScope.java | 11 ++++++++--- src/main/java/org/javacomp/parser/AstScanner.java | 1 + .../org/javacomp/project/FileSystemModuleManager.java | 2 ++ src/main/java/org/javacomp/project/Project.java | 1 + .../java/org/javacomp/reference/DefinitionSolver.java | 3 +++ .../handler/textdocument/DefinitionHandler.java | 4 ++++ 9 files changed, 30 insertions(+), 3 deletions(-) diff --git a/src/main/java/org/javacomp/completion/Completor.java b/src/main/java/org/javacomp/completion/Completor.java index 9afc5d4..f5dbef7 100644 --- a/src/main/java/org/javacomp/completion/Completor.java +++ b/src/main/java/org/javacomp/completion/Completor.java @@ -66,6 +66,8 @@ public CompletionResult getCompletionResult( Optional positionContext = PositionContext.createForPosition(moduleManager, filePath, line, contextColumn); + logger.fine("filePath: %s, line: %s, contextColumn: %s", filePath, line, contextColumn ); + if (!positionContext.isPresent()) { return CompletionResult.builder() .setCompletionCandidates(ImmutableList.of()) @@ -79,8 +81,10 @@ public CompletionResult getCompletionResult( ContentWithLineMap contentWithLineMap = ContentWithLineMap.create(positionContext.get().getFileScope(), fileManager, filePath); String prefix = contentWithLineMap.extractCompletionPrefix(line, column); + logger.fine("prefix:%s", prefix); // TODO: limit the number of the candidates. if (cachedCompletion.isIncrementalCompletion(filePath, line, column, prefix)) { + logger.fine("using cache"); return getCompletionCandidatesFromCache(line, column, prefix); } else { cachedCompletion = diff --git a/src/main/java/org/javacomp/completion/ContentWithLineMap.java b/src/main/java/org/javacomp/completion/ContentWithLineMap.java index f3fa0da..9e9056a 100644 --- a/src/main/java/org/javacomp/completion/ContentWithLineMap.java +++ b/src/main/java/org/javacomp/completion/ContentWithLineMap.java @@ -28,6 +28,7 @@ abstract class ContentWithLineMap { /** Gets the content before cursor position (line, column) as prefix for completion. */ String extractCompletionPrefix(int line, int column) { int position = LineMapUtil.getPositionFromZeroBasedLineAndColumn(getLineMap(), line, column); + logger.fine("column:%s, position:%s", column, position); if (position < 0) { logger.warning( "Position of (%s, %s): %s is negative when getting completion prefix for file %s", @@ -44,6 +45,7 @@ String extractCompletionPrefix(int line, int column) { while (start >= 0 && Character.isJavaIdentifierPart(getContent().charAt(start))) { start--; } + logger.fine("start:%s", start); return getContent().subSequence(start + 1, position).toString(); } diff --git a/src/main/java/org/javacomp/file/FileWatcher.java b/src/main/java/org/javacomp/file/FileWatcher.java index 96410d4..9c09b30 100644 --- a/src/main/java/org/javacomp/file/FileWatcher.java +++ b/src/main/java/org/javacomp/file/FileWatcher.java @@ -131,6 +131,7 @@ synchronized void shutdown() { } synchronized void notifyFileChange(Path path, WatchEvent.Kind eventKind) { + logger.fine("path: %s", path); if (PathUtils.shouldIgnorePath(path, projectRoot, ignorePathMatchers)) { return; } @@ -179,15 +180,18 @@ private void handleWatchEvent(Path dir, WatchEvent event) { Path fullPath = dir.resolve(event.context()); if (PathUtils.shouldIgnorePath(fullPath, projectRoot, ignorePathMatchers)) { + logger.fine("%s ignored", fullPath); return; } if (fileSnapshotPaths.contains(fullPath)) { + logger.fine("%s is on fileSnapshotPaths", fullPath); // The file is managed by file snapshots. Ignore file system events. return; } if (Files.isDirectory(fullPath)) { + logger.fine("%s is a directory", fullPath); handleDirectoryEvent(fullPath, eventKind); return; } @@ -196,6 +200,7 @@ private void handleWatchEvent(Path dir, WatchEvent event) { } private void handleDirectoryEvent(Path path, WatchEvent.Kind eventKind) { + logger.fine("path:%s", path); if (eventKind == StandardWatchEventKinds.ENTRY_CREATE) { // New directory created, watch it. watchNewDirectory(path); diff --git a/src/main/java/org/javacomp/model/PackageScope.java b/src/main/java/org/javacomp/model/PackageScope.java index 050f9a7..b5c1c05 100644 --- a/src/main/java/org/javacomp/model/PackageScope.java +++ b/src/main/java/org/javacomp/model/PackageScope.java @@ -11,10 +11,13 @@ import java.util.List; import java.util.Optional; import java.util.Set; +import org.javacomp.logging.JLogger; /** Scope of sub packages and files in a package. */ public class PackageScope implements EntityScope { - // Map of simple names -> subPackages. + static JLogger logger= JLogger.createForEnclosingClass(); + +// Map of simple names -> subPackages. private final Multimap subPackages; private final Set files; @@ -53,11 +56,13 @@ public void removePackage(PackageEntity entity) { } public void addFile(FileScope fileScope) { - files.add(fileScope); + if(!files.add(fileScope)) + logger.warning("couldn't add fileScope:%s", fileScope); } public void removeFile(FileScope fileScope) { - files.remove(fileScope); + if(!files.remove(fileScope)) + logger.warning("couln't remove fileScope:%s", fileScope); } /** @return whether the package has sub packages or files. */ diff --git a/src/main/java/org/javacomp/parser/AstScanner.java b/src/main/java/org/javacomp/parser/AstScanner.java index d2db3cc..7ee87d5 100644 --- a/src/main/java/org/javacomp/parser/AstScanner.java +++ b/src/main/java/org/javacomp/parser/AstScanner.java @@ -255,6 +255,7 @@ public Void visitMethod(MethodTree node, EntityScope currentScope) { methodEntity.setParameters(parameterListBuilder.build()); // TODO: distinguish between static and non-static methods. + logger.fine("fileScope:%s, methodEntity:%s", fileScope, methodEntity); currentScope.addEntity(methodEntity); List previousQualifiers = this.currentQualifiers; // No entity defined inside method scope is qualified. diff --git a/src/main/java/org/javacomp/project/FileSystemModuleManager.java b/src/main/java/org/javacomp/project/FileSystemModuleManager.java index 89b91f4..4b5bd0d 100644 --- a/src/main/java/org/javacomp/project/FileSystemModuleManager.java +++ b/src/main/java/org/javacomp/project/FileSystemModuleManager.java @@ -77,8 +77,10 @@ public synchronized void addOrUpdateFile(Path path, boolean fixContentForParsing } private void addOrUpdateFile(Module module, Path path, boolean fixContentForParsing) { + logger.fine("path:%s", path); try { Optional fileScope = parser.parseSourceFile(path, fixContentForParsing); + logger.fine("fileScope:%s", fileScope); if (fileScope.isPresent()) { module.addOrReplaceFileScope(fileScope.get()); } diff --git a/src/main/java/org/javacomp/project/Project.java b/src/main/java/org/javacomp/project/Project.java index 5c13ffa..22f203e 100644 --- a/src/main/java/org/javacomp/project/Project.java +++ b/src/main/java/org/javacomp/project/Project.java @@ -102,6 +102,7 @@ public synchronized void loadTypeIndexFile(String typeIndexFile) { private synchronized void addOrUpdateFile(Path filePath) { // Only fix content for files that are under completion. boolean fixContentForParsing = lastCompletedFile != null && lastCompletedFile.equals(filePath); + logger.fine("fixContentForParsing:%s", fixContentForParsing); moduleManager.addOrUpdateFile(filePath, fixContentForParsing); } diff --git a/src/main/java/org/javacomp/reference/DefinitionSolver.java b/src/main/java/org/javacomp/reference/DefinitionSolver.java index 3380694..5983f41 100644 --- a/src/main/java/org/javacomp/reference/DefinitionSolver.java +++ b/src/main/java/org/javacomp/reference/DefinitionSolver.java @@ -71,6 +71,7 @@ public List getDefinitionEntities( PositionContext.createForPosition(moduleManager, filePath, line, column); if (!positionContext.isPresent()) { + logger.fine("positionContext not present"); return ImmutableList.of(); } @@ -86,8 +87,10 @@ List getDefinitionEntities(Module module, PositionContext posi if (leafTree instanceof LiteralTree) { // LiteralTree is also an ExpressionTree. We don't want to show type definitions for literal // constants. + logger.fine("leafTree is a LiteralTree"); return ImmutableList.of(); } else if (leafTree instanceof ExpressionTree) { + logger.fine("leafTree is a ExpressionTree"); Set allowedKinds = ALLOWED_ENTITY_KINDS; if (treeIsMethodName(leafTree, parentTree)) { // parentTree is the method we need to solve. diff --git a/src/main/java/org/javacomp/server/handler/textdocument/DefinitionHandler.java b/src/main/java/org/javacomp/server/handler/textdocument/DefinitionHandler.java index 11f1c13..211111e 100644 --- a/src/main/java/org/javacomp/server/handler/textdocument/DefinitionHandler.java +++ b/src/main/java/org/javacomp/server/handler/textdocument/DefinitionHandler.java @@ -4,6 +4,7 @@ import java.nio.file.Paths; import java.util.List; import java.util.Objects; +import org.javacomp.logging.JLogger; import org.javacomp.model.Entity; import org.javacomp.model.EntityScope; import org.javacomp.model.FileScope; @@ -22,6 +23,7 @@ * https://github.com/Microsoft/language-server-protocol/blob/master/protocol.md#textDocument_definition */ public class DefinitionHandler extends RequestHandler { + private static final JLogger logger=JLogger.createForEnclosingClass(); private final Server server; public DefinitionHandler(Server server) { @@ -43,6 +45,7 @@ public List handleRequest(Request request) return definitions.stream() .map( entity -> { + logger.fine("getting location for %s", entity); com.google.common.collect.Range range = entity.getSymbolRange(); EntityScope scope = entity.getScope(); while (!(scope instanceof FileScope) && scope.getParentScope().isPresent()) { @@ -58,6 +61,7 @@ public List handleRequest(Request request) // If the file scope is not created from a source code (e.g. it's created from // a type index JSON file or class file), there is no souce code that defines the // symbol. + logger.fine("%s is on a non SOURCE_COCE fileScope"); return null; } if (!fileScope.getLineMap().isPresent()) { From 6a86bd77e95bcc7f656106a5c4ef1d5d710bf596 Mon Sep 17 00:00:00 2001 From: Nicolas Carranza Date: Sat, 2 May 2020 02:50:51 -0500 Subject: [PATCH 3/5] Set up JLogger before using logger.info() --- src/main/java/org/javacomp/server/JavaComp.java | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/src/main/java/org/javacomp/server/JavaComp.java b/src/main/java/org/javacomp/server/JavaComp.java index f81e469..44b2b54 100644 --- a/src/main/java/org/javacomp/server/JavaComp.java +++ b/src/main/java/org/javacomp/server/JavaComp.java @@ -122,17 +122,18 @@ public synchronized void initialize( if (initializeOptions != null) { mergeOptions(options, initializeOptions); } - - logger.info("Initializing project: %s", projectRootUri); - logger.info( - "Options:\n logPath: %s\n logLevel: %s\n" + " ignorePaths: %s\n typeIndexFiles: %s", - options.logPath, options.logLevel, options.ignorePaths, options.typeIndexFiles); + if (options.logPath != null) { JLogger.setLogFile(options.logPath); } if (options.logLevel != null) { JLogger.setLogLevel(options.getLogLevel()); } + logger.info("Initializing project: %s", projectRootUri); + logger.info( + "Options:\n logPath: %s\n logLevel: %s\n" + " ignorePaths: %s\n typeIndexFiles: %s", + options.logPath, options.logLevel, options.ignorePaths, options.typeIndexFiles); + if (options.ignorePaths != null) { ignorePaths = options.getIgnorePaths(); } else { From 0e2b953d53241e103e6c833a42a1f0b5b90203ab Mon Sep 17 00:00:00 2001 From: Nicolas Carranza Date: Sat, 2 May 2020 04:02:53 -0500 Subject: [PATCH 4/5] Fix lineMap position mismatch LineMap.getPosition(line,col) expands tabs to spaces causing position mismatch when editing source files with tabs, use getStartPosition instead. --- src/main/java/org/javacomp/parser/LineMapUtil.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/main/java/org/javacomp/parser/LineMapUtil.java b/src/main/java/org/javacomp/parser/LineMapUtil.java index ce13949..a601106 100644 --- a/src/main/java/org/javacomp/parser/LineMapUtil.java +++ b/src/main/java/org/javacomp/parser/LineMapUtil.java @@ -7,7 +7,7 @@ public final class LineMapUtil { private LineMapUtil() {} public static int getPositionFromZeroBasedLineAndColumn(LineMap lineMap, int line, int column) { - // LineMap accepts 1-based line and column numbers. - return (int) lineMap.getPosition(line + 1, column + 1); + // LineMap accepts 1-based line. + return (int)lineMap.getStartPosition(line+1)+column; } } From 3532763ce6ffdbb384bc714d8f6497c73591a237 Mon Sep 17 00:00:00 2001 From: Nicolas Carranza Date: Sat, 2 May 2020 05:22:20 -0500 Subject: [PATCH 5/5] Fix CompletionResult.isIncrementalCompletion when prefix length is 0 --- src/main/java/org/javacomp/completion/CompletionResult.java | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/main/java/org/javacomp/completion/CompletionResult.java b/src/main/java/org/javacomp/completion/CompletionResult.java index a2597d0..ecdf51c 100644 --- a/src/main/java/org/javacomp/completion/CompletionResult.java +++ b/src/main/java/org/javacomp/completion/CompletionResult.java @@ -31,6 +31,9 @@ public static Builder builder() { * the cached completion. */ boolean isIncrementalCompletion(Path filePath, int line, int column, String prefix) { + if(prefix.length()==0){ + return false; + } if (!getFilePath().equals(filePath)) { return false; }