Skip to content

Commit e95e02f

Browse files
committed
update execution log
1 parent 586aa48 commit e95e02f

File tree

1 file changed

+93
-28
lines changed

1 file changed

+93
-28
lines changed

docs/recipes/execution-log.md

+93-28
Original file line numberDiff line numberDiff line change
@@ -143,35 +143,35 @@ Similar to other Lucee class definitions, you can specify:
143143

144144
When creating custom implementations, you can focus on the specific logging functionality while leveraging Lucee's timing and threshold capabilities through the provided interface.
145145

146-
### Available Properties
146+
### Common Arguments
147147

148-
When configuring an ExecutionLog, you can specify the following arguments:
148+
When configuring any ExecutionLog implementation, you can specify these arguments:
149149

150-
| Property | Description | Default |
151-
|----------|-------------|---------|
152-
| `min-time` | Minimum execution time to log (in ns, µs, ms, or s) | 0 |
153-
| `unit` | Output time unit (`nano`, `micro`, or `milli`) | `nano` |
150+
| Property | Description | Default | Example Values |
151+
|----------|-------------|---------|---------------|
152+
| `min-time` | Minimum execution time threshold for logging. Only statements taking longer than this threshold will be logged. Can be specified with time unit suffixes. | 0 | `"500ns"`, `"10µs"`, `"5ms"`, `"0.1s"` |
153+
| `unit` | The time unit to use in log output. Affects readability based on your performance targets. | `nano` | `"nano"` (nanoseconds), `"micro"` (microseconds), `"milli"` (milliseconds) |
154154

155155
### ConsoleExecutionLog Arguments
156156

157-
| Property | Description | Default |
158-
|----------|-------------|---------|
159-
| `stream-type` | Output stream to use (`error` or `out`) | `out` |
160-
| `snippet` | Include code snippet in output | `false` |
157+
| Property | Description | Default | Notes |
158+
|----------|-------------|---------|-------|
159+
| `stream-type` | Determines whether to output to standard out or standard error. Use `error` to separate log output from regular application output. | `out` | `"out"` or `"error"` |
160+
| `snippet` | When enabled, captures and displays the actual CFML code being executed. Extremely useful for identifying exactly which code is causing performance issues, especially in complex templates with many expressions. | `false` | Set to `true` to see the actual code being executed |
161161

162162
### ResourceExecutionLog Arguments
163163

164-
| Property | Description | Default |
165-
|----------|-------------|---------|
166-
| `directory` | Directory to store log files | Temp directory |
164+
| Property | Description | Default | Notes |
165+
|----------|-------------|---------|-------|
166+
| `directory` | Specifies where log files should be stored. If not provided, Lucee will use a temp directory. For persistent logs, specify an absolute path. Lucee's virtual filesystem support means you can write to various destinations (S3, HTTP, etc.). | Lucee temp directory | `"/var/logs/lucee"`, `"s3://my-bucket/logs"` |
167167

168168
### LogExecutionLog Arguments
169169

170-
| Property | Description | Default |
171-
|----------|-------------|---------|
172-
| `log-level` | Log level (`trace`, `debug`, `info`, etc.) | `trace` |
173-
| `log-name` | Logger name | `lucee.runtime.engine.Controler` |
174-
| `snippet` | Include code snippet in output | `false` |
170+
| Property | Description | Default | Notes |
171+
|----------|-------------|---------|-------|
172+
| `log-level` | Sets the severity level for log entries. Controls visibility in consolidated logs and allows filtering when reviewing. | `trace` | `"trace"`, `"debug"`, `"info"`, `"warn"`, `"error"` |
173+
| `log-name` | Customizes the logger name for better organization and filtering in consolidated logs. | `lucee.runtime.engine.Controler` | `"execution"`, `"performance"`, `"myapp.performance"` |
174+
| `snippet` | When enabled, captures and displays the actual CFML code being executed alongside timing information. Particularly valuable when analyzing logs after execution. | `false` | Set to `true` to include source code in logs |
175175

176176
### Example Log Implementation Configuration
177177

@@ -195,23 +195,63 @@ When configuring an ExecutionLog, you can specify the following arguments:
195195

196196
### ConsoleExecutionLog
197197

198+
Without snippets:
198199
```
199200
1234567890:C:/websites/myapp/index.cfm:45:72 > 123 ns
200201
1234567890:C:/websites/myapp/index.cfm:75:120 > 789 ns
201202
```
202203

203-
With `snippet` enabled:
204+
With `snippet` enabled (shows the actual code being executed):
204205
```
205206
1234567890:C:/websites/myapp/index.cfm:45:72 > 123 ns [<cfset result = myFunction(arg1, arg2)>]
206207
```
207208

209+
In this example:
210+
- `1234567890` is the request ID
211+
- `C:/websites/myapp/index.cfm` is the template path
212+
- `45:72` represents the start and end position of the code in the template
213+
- `123 ns` is the execution time
214+
- `[<cfset result = myFunction(arg1, arg2)>]` is the actual code snippet (when enabled)
215+
208216
### ResourceExecutionLog
209217

210-
Creates a structured log file with:
211-
- HTTP request information
212-
- Execution time summary
213-
- Detailed path mappings
214-
- Statement execution metrics
218+
Creates a structured log file with multiple sections:
219+
220+
1. **Header Information**:
221+
```
222+
context-path:/myapp
223+
remote-user:
224+
remote-addr:127.0.0.1
225+
remote-host:localhost
226+
script-name:/myapp/index.cfm
227+
server-name:localhost
228+
protocol:HTTP/1.1
229+
server-port:8888
230+
path-info:
231+
query-string:
232+
unit:ms
233+
min-time-nano:1000000
234+
execution-time:5462
235+
```
236+
237+
2. **Path Mappings**:
238+
```
239+
0:/myapp/index.cfm
240+
1:/myapp/components/service.cfc
241+
```
242+
243+
3. **Execution Metrics**:
244+
```
245+
0 45 72 12
246+
0 75 120 2
247+
1 128 170 56
248+
```
249+
250+
Each line in the execution metrics contains:
251+
- Template index (from path mappings)
252+
- Start position
253+
- End position
254+
- Execution time (in the configured unit)
215255

216256
## Performance Considerations
217257

@@ -230,7 +270,32 @@ ExecutionLog has a significant performance impact and should only be enabled in
230270

231271
## Use Cases
232272

233-
- Identifying performance bottlenecks within complex templates
234-
- Profiling specific code blocks for optimization
235-
- Debugging execution flow in complex applications
236-
- Performance regression testing
273+
### Performance Optimization
274+
275+
- **Identifying Hotspots**: Find the most time-consuming statements in your application
276+
- **Function Analysis**: Determine which function calls or methods consume disproportionate resources
277+
- **Query Performance**: Track the execution time of database queries embedded in your code
278+
- **Component Analysis**: Compare different components or services in your application architecture
279+
280+
### Debugging
281+
282+
- **Execution Flow Analysis**: Understand the order and timing of code execution
283+
- **Slow Request Investigation**: Troubleshoot specific slow requests in production environments
284+
- **Cache Effectiveness**: Verify if caching strategies are working as expected
285+
- **Performance Regression Testing**: Monitor for degradation when making code changes
286+
287+
### Development Guidance
288+
289+
- **Code Refactoring**: Identify candidates for optimization or refactoring
290+
- **Best Practice Enforcement**: Detect patterns that violate performance best practices
291+
- **Developer Education**: Help team members understand performance implications of their code
292+
293+
### Real-World Example
294+
295+
Consider a Lucee application that begins experiencing intermittent slowdowns. By enabling ExecutionLog with snippets, you might discover:
296+
297+
```
298+
1234567890:C:/websites/myapp/services/userService.cfc:245:270 > 1250 ms [<cfset user = entityLoad("User", {email=arguments.email})>]
299+
```
300+
301+
This immediately shows that a particular ORM entityLoad operation is taking over a second to execute, pinpointing the exact line of code causing the performance issue.

0 commit comments

Comments
 (0)