LDEV-5206 ExecutionLog improvements (#2458)

core/src/main/java/lucee/runtime/PageSourceImpl.java

@@ -90,6 +90,7 @@ public final class PageSourceImpl implements PageSource {
 	private long lastAccess;
 	private RefIntegerSync accessCount = new RefIntegerSync();
 	private boolean flush = false;
+	private int sourceOffset; // used to track when wrapping in cfscript tag
 
 	private static class PageAndClassName {
 		private Page page;
@@ -1156,4 +1157,17 @@ public void resetLoaded() {
 		Page p = pcn.page;
 		if (p != null) p.setLoadType((byte) 0);
 	}
+
+	@Override
+	public void setSourceOffset(int sourceOffset) {
+		this.sourceOffset = sourceOffset;
+	}
+
+	@Override
+	public int getSourceOffset() {
+		//lucee.aprint.o("sourceOffset:"+ sourceOffset);
+		return sourceOffset;
+	}
+
+
 }

core/src/main/java/lucee/runtime/debug/DebuggerImpl.java

@@ -108,7 +108,7 @@ public final class DebuggerImpl implements Debugger {
 	private static final Collection.Key GENERIC_DATA = KeyConstants._genericData;
 	private static final Collection.Key PAGE_PARTS = KeyConstants._pageParts;
 
-	private static final int MAX_PARTS = 100;
+	private static final int MAX_PARTS = Caster.toIntValue(SystemUtil.getSystemPropOrEnvVar("lucee.debugging.maxPageParts", null), 0);
 
 	private final Map<String, DebugEntryTemplateImpl> entries = new HashMap<String, DebugEntryTemplateImpl>();
 	private Map<String, DebugEntryTemplatePartImpl> partEntries;
@@ -236,7 +236,7 @@ public DebugEntryTemplatePart getEntry(PageContext pc, PageSource source, int st
 			if (de != null) {
 				de.countPP();
 				return de;
-			}
+			} 
 		}
 		else {
 			partEntries = new HashMap<String, DebugEntryTemplatePartImpl>();
@@ -559,26 +559,33 @@ public Struct getDebuggingData(PageContext pc, boolean addAddionalInfo) throws D
 		int qrySize = 0;
 		Query qryPart = null;
 		if (hasParts) {
-			String slowestTemplate = arrPages.get(0).getPath();
-			List<DebugEntryTemplatePart> filteredPartEntries = new ArrayList();
 			java.util.Collection<DebugEntryTemplatePartImpl> col = partEntries.values();
-			for (DebugEntryTemplatePart detp: col) {
+			List<DebugEntryTemplatePart> filteredPartEntries = new ArrayList<DebugEntryTemplatePart>();
+			DebugEntryTemplatePart[] parts = new DebugEntryTemplatePart[qrySize];
+			if (MAX_PARTS == 0 || col.size() < MAX_PARTS){
+				qrySize = col.size();
+				parts = new DebugEntryTemplatePart[qrySize];
+				filteredPartEntries.addAll(col);
+				parts = filteredPartEntries.toArray(parts);
+			} else {
+				// TODO add slowest templates till we reach MAX_PARTS, currently just grabs only the slowest template's parts
+				String slowestTemplate = arrPages.get(0).getPath();
+				for (DebugEntryTemplatePart detp: col) {
+					if (detp.getPath().equals(slowestTemplate)) filteredPartEntries.add(detp);
+				}
+				qrySize = Math.min(filteredPartEntries.size(), MAX_PARTS);
+				parts = new DebugEntryTemplatePart[qrySize];
 
-				if (detp.getPath().equals(slowestTemplate)) filteredPartEntries.add(detp);
-			}
-			qrySize = Math.min(filteredPartEntries.size(), MAX_PARTS);
+				Collections.sort(filteredPartEntries, DEBUG_ENTRY_TEMPLATE_PART_COMPARATOR);
+
+				if (filteredPartEntries.size() > MAX_PARTS) parts = filteredPartEntries.subList(0, MAX_PARTS).toArray(parts);
+				else parts = filteredPartEntries.toArray(parts);
+			}	
 
 			qryPart = new QueryImpl(PAGE_PART_COLUMNS, qrySize, "query");
 			debugging.setEL(PAGE_PARTS, qryPart);
 
 			int row = 0;
-			Collections.sort(filteredPartEntries, DEBUG_ENTRY_TEMPLATE_PART_COMPARATOR);
-
-			DebugEntryTemplatePart[] parts = new DebugEntryTemplatePart[qrySize];
-
-			if (filteredPartEntries.size() > MAX_PARTS) parts = filteredPartEntries.subList(0, MAX_PARTS).toArray(parts);
-			else parts = filteredPartEntries.toArray(parts);
-
 			try {
 				DebugEntryTemplatePart de;
 				// PageSource ps;

core/src/main/java/lucee/runtime/engine/ConsoleExecutionLog.java

@@ -21,41 +21,55 @@
 import java.io.PrintWriter;
 import java.util.Map;
 
-import lucee.commons.io.log.Log;
-import lucee.commons.io.log.LogUtil;
+import lucee.commons.io.res.util.ResourceSnippet;
+import lucee.commons.io.res.util.ResourceSnippetsMap;
 import lucee.runtime.PageContext;
+import lucee.runtime.PageSource;
+import lucee.runtime.PageContextImpl;
+import lucee.runtime.op.Caster;
 
 public class ConsoleExecutionLog extends ExecutionLogSupport {
 
 	private PrintWriter pw;
 	private PageContext pc;
+	private ResourceSnippetsMap snippetsMap = new ResourceSnippetsMap(1024, 128);
+	private boolean snippet = false;
 
 	@Override
 	protected void _init(PageContext pc, Map<String, String> arguments) {
 		this.pc = pc;
-
+		if (Caster.toBooleanValue(arguments.get("snippet"), false)) snippet = true;
 		if (pw == null) {
 			// stream type
 			String type = arguments.get("stream-type");
-			if (type != null && type.trim().equalsIgnoreCase("error")) pw = new PrintWriter(System.err);
+			if (type.trim().equalsIgnoreCase("error")) pw = new PrintWriter(System.err);
 			else pw = new PrintWriter(System.out);
-
 		}
 	}
 
 	@Override
 	protected void _log(int startPos, int endPos, long startTime, long endTime) {
-
+		PageSource ps = pc.getCurrentPageSource(null);
+		if (ps == null) return;
 		long diff = endTime - startTime;
-		LogUtil.log(pc, Log.LEVEL_TRACE, Controler.class.getName(),
-				pc.getId() + ":" + pc.getCurrentPageSource().getDisplayPath() + ":" + positons(startPos, endPos) + " > " + timeLongToString(diff));
+		String log = pc.getId() + ":" + ps.getDisplayPath() + ":";
+		if (snippet) {
+			ResourceSnippet snippet = snippetsMap.getSnippet(ps, startPos, endPos, ((PageContextImpl) pc).getResourceCharset().name());
+			log += positions(snippet.getEndLine(), snippet.getEndLine()) + " > " + timeLongToString(diff) + " [" + snippet.getContent() + "]";
+		} else {
+			log += positions(startPos, endPos) + " > " + timeLongToString(diff);
+		}
+		pw.print(log + "\n");
+		pw.flush();
 	}
 
 	@Override
 	protected void _release() {
+		//if (pw != null) pw.close();
+		snippetsMap = null;
 	}
 
-	private static String positons(int startPos, int endPos) {
+	private static String positions(int startPos, int endPos) {
 		if (startPos == endPos) return startPos + "";
 		return startPos + ":" + endPos;
 	}

core/src/main/java/lucee/runtime/engine/DebugExecutionLog.java

@@ -21,6 +21,7 @@
 import java.util.Map;
 
 import lucee.runtime.PageContext;
+import lucee.runtime.PageSource;
 import lucee.runtime.debug.DebugEntry;
 import lucee.runtime.util.PageContextUtil;
 
@@ -37,12 +38,14 @@ protected void _init(PageContext pc, Map<String, String> arguments) {
 	protected void _log(int startPos, int endPos, long startTime, long endTime) {
 
 		if (!PageContextUtil.debug(pc)) return;
-
+		PageSource ps = pc.getCurrentPageSource(null);
+		if (ps == null) return;
+
 		long diff = endTime - startTime;
 		if (unit == UNIT_MICRO) diff /= 1000;
 		else if (unit == UNIT_MILLI) diff /= 1000000;
 
-		DebugEntry de = pc.getDebugger().getEntry(pc, pc.getCurrentPageSource(), startPos, endPos);
+		DebugEntry de = pc.getDebugger().getEntry(pc, ps, startPos, endPos);
 		de.updateExeTime((int) diff);
 	}
 

core/src/main/java/lucee/runtime/engine/LogExecutionLog.java

@@ -0,0 +1,76 @@
+/**
+ *
+ * Copyright (c) 2014, the Railo Company Ltd. All rights reserved.
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either 
+ * version 2.1 of the License, or (at your option) any later version.
+ * 
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ * 
+ * You should have received a copy of the GNU Lesser General Public 
+ * License along with this library.  If not, see <http://www.gnu.org/licenses/>.
+ * 
+ **/
+package lucee.runtime.engine;
+
+import java.io.PrintWriter;
+import java.util.Map;
+
+import lucee.commons.io.log.Log;
+import lucee.commons.io.log.LogUtil;
+import lucee.commons.io.res.util.ResourceSnippet;
+import lucee.commons.io.res.util.ResourceSnippetsMap;
+import lucee.commons.lang.StringUtil;
+import lucee.runtime.PageContext;
+import lucee.runtime.PageSource;
+import lucee.runtime.PageContextImpl;
+import lucee.runtime.op.Caster;
+
+public class LogExecutionLog extends ExecutionLogSupport {
+
+	private PageContext pc;
+	private ResourceSnippetsMap snippetsMap = new ResourceSnippetsMap(1024, 128);
+	private boolean snippet = false;
+	private int logLevel;
+	private String logName;
+
+	@Override
+	protected void _init(PageContext pc, Map<String, String> arguments) {
+		this.pc = pc;
+		if (Caster.toBooleanValue(arguments.get("snippet"), false)) snippet = true;
+		String type = arguments.get("log-level");
+		logLevel = LogUtil.toLevel(type, Log.LEVEL_TRACE);
+		logName = StringUtil.toString(arguments.get("log-name"), Controler.class.getName());
+	}
+
+	@Override
+	protected void _log(int startPos, int endPos, long startTime, long endTime) {
+		PageSource ps = pc.getCurrentPageSource(null);
+		if (ps == null) return;
+		long diff = endTime - startTime;
+		String log = pc.getId() + ":" + ps.getDisplayPath() + ":";
+		if (snippet) {
+			ResourceSnippet snippet = snippetsMap.getSnippet(ps, startPos, endPos, ((PageContextImpl) pc).getResourceCharset().name());
+			log += positions(snippet.getEndLine(), snippet.getEndLine()) + " > " + timeLongToString(diff) + " [" + snippet.getContent() + "]";
+		} else {
+			log += positions(startPos, endPos) + " > " + timeLongToString(diff);
+		}
+		LogUtil.log(pc, logLevel, Controler.class.getName(), log);
+	}
+
+	@Override
+	protected void _release() {
+		snippetsMap = null;
+	}
+
+	private static String positions(int startPos, int endPos) {
+		if (startPos == endPos) return startPos + "";
+		return startPos + ":" + endPos;
+	}
+
+}

core/src/main/java/lucee/transformer/bytecode/util/ExpressionUtil.java

@@ -158,7 +158,7 @@ private static void call_Log(BytecodeContext bc, Method method, Position pos, St
 			GeneratorAdapter adapter = bc.getAdapter();
 			adapter.loadArg(0);
 			// adapter.checkCast(Types.PAGE_CONTEXT_IMPL);
-			adapter.push(pos.pos);
+			adapter.push(pos.pos - bc.getPageSource().getSourceOffset());
 			adapter.push(id);
 			adapter.invokeVirtual(Types.PAGE_CONTEXT, method);
 		}

core/src/main/java/lucee/transformer/cfml/tag/CFMLTransformer.java

@@ -165,7 +165,8 @@ public Page transform(Factory factory, ConfigPro config, PageSource ps, TagLib[]
 
 					// try inside a cfscript
 					String text = "<" + scriptTag.getFullName() + ">" + original.getText() + "\n</" + scriptTag.getFullName() + ">";
-					sc = new PageSourceCode(ps, text, charset, writeLog);
+					int sourceOffset = ("<" + scriptTag.getFullName() + ">").length();
+					sc = new PageSourceCode(ps, text, charset, writeLog, sourceOffset);
 				}
 
 				p = transform(factory, config, sc, tlibs, flibs, ps.getResource().lastModified(), dotUpper, returnValue, ignoreScopes);
@@ -198,14 +199,15 @@ public Page transform(Factory factory, ConfigPro config, PageSource ps, TagLib[]
 
 			// try inside a cfscript
 			String text = "<" + scriptTag.getFullName() + ">" + original.getText() + "\n</" + scriptTag.getFullName() + ">";
-			sc = new PageSourceCode(ps, text, charset, writeLog);
+			int sourceOffset = ("<" + scriptTag.getFullName() + ">").length();
+			sc = new PageSourceCode(ps, text, charset, writeLog, sourceOffset);
 
 			try {
 				while (true) {
 					if (sc == null) {
 						sc = new PageSourceCode(ps, charset, writeLog);
 						text = "<" + scriptTag.getFullName() + ">" + sc.getText() + "\n</" + scriptTag.getFullName() + ">";
-						sc = new PageSourceCode(ps, text, charset, writeLog);
+						sc = new PageSourceCode(ps, text, charset, writeLog, sourceOffset);
 					}
 					try {
 						_p = transform(factory, config, sc, tlibs, flibs, ps.getResource().lastModified(), dotUpper, returnValue, ignoreScopes);

core/src/main/java/lucee/transformer/util/PageSourceCode.java

@@ -44,6 +44,13 @@ public PageSourceCode(PageSource ps, String text, Charset charset, boolean write
 		this.ps = ps;
 	}
 
+	public PageSourceCode(PageSource ps, String text, Charset charset, boolean writeLog, int sourceOffset) {
+		super(null, text, writeLog);
+		this.charset = charset;
+		this.ps = ps;
+		ps.setSourceOffset(sourceOffset);
+	}
+
 	public static String toString(PageSource ps, Charset charset) throws IOException {
 		String content;
 		InputStream is = null;

core/src/main/java/resource/setting/sysprop-envvar.json

@@ -398,5 +398,10 @@
         "sysprop": "lucee.threads.maxDefault",
         "envvar": "LUCEE_THREADS_MAXDEFAULT",
         "desc": "Sets the default max number of parallel threads, default 20"
+    },
+    {
+        "sysprop": "lucee.debugging.maxPageParts",
+        "envvar": "LUCEE_DEBUGGING_MAXPAGEPARTS",
+        "desc": "Maximum number of debugging page parts (executionLogs to output), 0 to disable max limit"
     }
 ]

loader/src/main/java/lucee/runtime/PageSource.java

@@ -182,4 +182,8 @@ public interface PageSource extends Serializable {
 	 */
 	public boolean executable();
 
+	public abstract void setSourceOffset(int sourceOffset);
+
+	public abstract int getSourceOffset();
+
 }