---
title: "Logging a data.table pipeline"
output: rmarkdown::html_vignette
vignette: >
  %\VignetteIndexEntry{Logging a data.table pipeline}
  %\VignetteEngine{knitr::rmarkdown}
  %\VignetteEncoding{UTF-8}
---

```{r setup, include = FALSE}
knitr::opts_chunk$set(
  collapse = TRUE,
  comment = "#>"
)
```

`data.table` says very little about what it did. `DT[i, j, by]` returns a
table, and whether the filter dropped two rows or two thousand, whether the
join matched anything, whether `:=` overwrote a column you meant to keep, is
something you have to check yourself, one `nrow()` at a time.

`dtlog` prints it instead. It redefines `[.data.table` and the `data.table`
functions around it so that every operation reports what it did, and leaves the
operations themselves untouched -- same return value, same visibility, same
modification by reference. It is the idea behind
[tidylog](https://github.com/elbersb/tidylog), applied to `data.table`.

This vignette follows one pipeline from a CSV file to a summary table, reading
the log as it goes, and then writes the whole session to a transcript file.
The README covers the reference material: the full list of what is logged, the
comparison with tidylog, and the timings.

## Loading

`dtlog` masks functions that `data.table` exports, so it has to come after
`data.table` on the search path. Load it last, or there will be no output.

```{r load, message = FALSE}
library(data.table)
library(dtlog)
```

```{r vignette-option, include = FALSE}
options(dtlog.log_from_packages = TRUE)
```

By default `dtlog` only reports calls made from the global environment, so
`data.table` code inside other packages stays silent. Code in a vignette is not
run from the global environment either, so this vignette sets
`options(dtlog.log_from_packages = TRUE)` once, up front. In an ordinary
session you do not need it.

## The data

Two tables: repeated measurements, and one row per patient.

```{r data}
set.seed(42)

visits <- data.table(
  id    = rep(1:20, each = 3),
  visit = rep(1:3, times = 20),
  date  = as.Date("2026-01-01") + sample(0:180, 60, replace = TRUE),
  sbp   = round(rnorm(60, mean = 132, sd = 16)),
  crp   = round(rexp(60, rate = 1 / 8), 1)
)
visits[sample(60, 6), sbp := NA_real_]

patients <- data.table(
  id  = 1:20,
  sex = sample(c("F", "M"), 20, replace = TRUE),
  age = sample(45:85, 20, replace = TRUE),
  arm = rep(c("control", "treatment"), each = 10)
)
patients <- patients[id != 7]   # one patient never made it into the registry
```

`data.table()` itself is not wrapped, so building the two tables is silent; the
`:=` that writes the missing values and the filter that drops a patient are
not. Writing the patient table out and reading it back shows the file end of
things.

```{r io}
path <- tempfile(fileext = ".csv")
fwrite(patients, path)
patients <- fread(path)
```

`fread()` reports what it read and from where, `fwrite()` what it wrote. Both
messages name the file, which is the part that is easy to get wrong in a script
that builds paths.

## Cleaning

Everything below is ordinary `data.table` code. The `#>` lines are `dtlog`.

```{r clean}
visits <- na.omit(visits, cols = "sbp")

visits[, high := sbp >= 140]

visits[crp > 25, crp := NA_real_]
```

Three messages worth reading closely:

* `drop_na` gives the rows removed and the rows left, so a `cols =` argument
  that matches nothing is visible immediately.
* the first `:=` is a new column: name, type, how many distinct values, how
  much of it is `NA`.
* the second `:=` writes into a column that already exists, so the message is
  about change -- how many values moved, and how many `NA`s that created. A
  recode that silently hits far more rows than expected shows up here.

Dropping a column and renaming one are logged the same way:

```{r rename}
visits[, high := NULL]

setnames(visits, "sbp", "sbp_mmhg")
```

`setnames()` prints both names, `sbp -> sbp_mmhg`, so the log stays readable
when several renames happen in a row.

## Joining

```{r join}
merged <- merge(visits, patients, by = "id", all.x = TRUE)
```

The join message has two halves: the columns that arrived, and the matching
counts. The counts are the useful half here -- the `rows only in visits` line
is the patient who never made it into the registry, three visits with no `arm`
and no `age`. A left join keeps them, the row count does not change, and
without the log nothing about the result says anything happened.

Now that the log has pointed at them, they can go:

```{r drop-unmatched}
merged <- merged[!is.na(arm)]
```

The same join written as a `data.table` subset logs the columns and the change
in rows:

```{r join-i}
setkey(patients, id)
joined <- visits[patients, on = "id"]
```

`setkey()` reports the key it set and how many rows it sorted; the subset
reports the join.

## Reshaping and aggregating

```{r reshape}
wide <- dcast(merged, id + arm ~ visit, value.var = "sbp_mmhg")
```

`dcast()` reports the shape before and after, which is where a reshape usually
goes wrong: an unexpected row count means the left hand side of the formula
does not identify a row.

Aggregation is logged in two lines, the grouping and the result:

```{r summarise}
by_arm <- merged[, .(n        = .N,
                     patients = uniqueN(id),
                     mean_sbp = mean(sbp_mmhg),
                     mean_crp = mean(crp, na.rm = TRUE)),
                 by = arm]
by_arm
```

`dtlog` distinguishes the rows `i` selects from the rows `j` produces. When `j`
aggregates, the row count is not blamed on the filter:

```{r i-vs-j}
merged[age >= 65, .(mean_sbp = mean(sbp_mmhg)), by = arm]
```

The same holds in a pipe. `x |> f(y)` reaches `dtlog` as an ordinary call to
`f(x, y)`, so a piped chain logs exactly like a nested one:

```{r pipe, eval = getRversion() >= "4.3.0"}
merged[arm == "treatment"] |>
  _[, .(mean_crp = mean(crp, na.rm = TRUE)), by = sex]
```

## Writing the session to a file

`dt_log()` opens a transcript. From that point on every operation is appended
to a text file together with the call that produced it, and `dt_log_end()`
closes it. This is the part that is hard to reproduce by hand: a record of what
a script actually did to the data, next to the code that did it.

```{r transcript}
log_path <- tempfile(fileext = ".txt")
dt_log(log_path)

final <- merged[!is.na(crp)]
final[, crp_log := log(crp)]
summary_tbl <- final[, .(n = .N, mean_crp_log = mean(crp_log)), by = .(arm, sex)]

dt_log_end()
```

The file holds the calls as R deparses them, with their messages underneath:

```{r transcript-show, comment = ""}
cat(readLines(log_path), sep = "\n")
```

`dt_log(append = TRUE)` adds to an existing file, `code = FALSE` writes the
messages without the calls, and `echo = FALSE` writes only to the file and
leaves the console quiet. `dt_log_file()` returns the path of the open
transcript, or `NULL`:

```{r transcript-file}
dt_log_file()
```

The file is flushed after every operation, so it is readable while a long
script is still running, and a session that ends without `dt_log_end()` still
leaves a complete file -- only the closing line is missing.

## Turning the volume down

A long pipeline in a loop does not need a message per iteration.
`dtlog_pause()` and `dtlog_resume()` bracket a block of code:

```{r pause}
dtlog_pause()
for (i in 1:3) merged[, tmp := i]
dtlog_resume()

merged[, tmp := NULL]
```

`options(dtlog.detail = "compact")` keeps the messages but drops the
value-level detail -- types, unique values, share of `NA`, number of values
changed. It is also the setting that never copies data, so a `:=` on a large
table costs nothing:

```{r compact}
options(dtlog.detail = "compact")
merged[, crp_high := crp > 10]
options(dtlog.detail = "full")
```

`options(dtlog.display = ...)` decides where the output goes. The default is
`message()`; a list of functions sends each message to all of them, and an
empty list turns logging off without unloading the package:

```{r display}
options(dtlog.display = list(function(x) cat("LOG |", x, "\n")))
elderly <- merged[age >= 70]

options(dtlog.display = NULL)  # back to message()
```

Finally, `dtlog_summary()` describes a table and returns it unchanged, so it
can sit in the middle of a chain:

```{r summary}
dtlog_summary(merged)[1:2, .(id, arm)]
```

## What does not change

`dtlog` re-evaluates the call you wrote, unchanged, in the frame you wrote it
in. Return values and visibility are the same, `:=` and the `set*()` functions
still modify by reference, non-standard evaluation still works, and `setDT()`
still converts a variable in the caller. The package's parity tests run more
than a hundred `data.table` idioms twice -- once through `dtlog`, once through
`data.table` -- and compare the value, its visibility and the state of the
inputs.

```{r cleanup, include = FALSE}
unlink(c(path, log_path))
```