Skip to content

Commit a1c14f3

Browse files
authored
[1/n] Optimize new tracing logger (#3040)
This implements two improvements to our new tracing logger. - Inline the different formats so that the compiler can optimize the callsite as much as possible. - Instead of allocating a string to represent the intermediate representation of the logs, we use a writer now to collect the log line as we visit the event. <!-- CURSOR_SUMMARY --> --- > [!NOTE] > Monomorphizes legacy text/JSON log formatting and writes events directly to the output, refactoring setup to select concrete formatters and integrate OTEL. > > - **Logger performance/structure**: > - Introduces `LegacyFormatter` trait with concrete `TextFormatter` and `JsonFormatter` that write directly to a `Write` target (no intermediate `String`). > - Replaces `LegacyFormatLayer<W>` with `LegacyFormatLayer<W, F>` generic over formatter, enabling inlined, monomorphized `on_event` paths. > - `TextFormatter` outputs fern-compatible text; `JsonFormatter` builds JSON via `serde_json::to_writer`. > - New `DirectWriteVisitor` writes the `message` field directly; `MessageVisitor` simplified for JSON extraction. > - **Setup refactor**: > - `setup_legacy_format` now matches on `(format, export_to, stdout)` to instantiate concrete formatters and writers (stdout or date-based file) and optionally attach OTEL via `create_otel_layer`. > - Signature updated to use `session_id`/`machine_id`; session ID inclusion handled by formatter construction. > > <sup>Written by [Cursor Bugbot](https://cursor.com/dashboard?tab=bugbot) for commit cb1895c. This will update automatically on new commits. Configure [here](https://cursor.com/dashboard?tab=bugbot).</sup> <!-- /CURSOR_SUMMARY -->
1 parent 3d1c6ba commit a1c14f3

File tree

1 file changed

+203
-95
lines changed

1 file changed

+203
-95
lines changed

apps/framework-cli/src/cli/logger.rs

Lines changed: 203 additions & 95 deletions
Original file line numberDiff line numberDiff line change
@@ -270,94 +270,168 @@ struct CustomFields {
270270
machine_id: String,
271271
}
272272

273-
/// Layer that formats logs to match the legacy fern format exactly
274-
struct LegacyFormatLayer<W> {
275-
writer: W,
276-
format: LogFormat,
273+
/// Trait for formatting log events. Implementations are monomorphized,
274+
/// allowing the compiler to inline the format logic directly into `on_event`.
275+
///
276+
/// Formatters write directly to the provided writer to avoid intermediate allocations.
277+
trait LegacyFormatter {
278+
fn write_event<W: Write>(
279+
&self,
280+
writer: &mut W,
281+
level: &Level,
282+
target: &str,
283+
event: &Event<'_>,
284+
) -> std::io::Result<()>;
285+
}
286+
287+
/// Text formatter matching fern's text format exactly
288+
#[derive(Clone)]
289+
struct TextFormatter {
277290
include_session_id: bool,
278-
custom_fields: CustomFields,
291+
session_id: String,
279292
}
280293

281-
impl<W> LegacyFormatLayer<W> {
282-
fn new(
283-
writer: W,
284-
format: LogFormat,
285-
include_session_id: bool,
286-
custom_fields: CustomFields,
287-
) -> Self {
294+
impl TextFormatter {
295+
fn new(include_session_id: bool, session_id: String) -> Self {
288296
Self {
289-
writer,
290-
format,
291297
include_session_id,
292-
custom_fields,
298+
session_id,
293299
}
294300
}
301+
}
295302

296-
fn format_text(&self, level: &Level, target: &str, message: &str) -> String {
297-
// Match current fern text format exactly
298-
format!(
299-
"[{} {}{} - {}] {}",
303+
impl LegacyFormatter for TextFormatter {
304+
#[inline]
305+
fn write_event<W: Write>(
306+
&self,
307+
writer: &mut W,
308+
level: &Level,
309+
target: &str,
310+
event: &Event<'_>,
311+
) -> std::io::Result<()> {
312+
// Write prefix: [timestamp LEVEL - target]
313+
write!(
314+
writer,
315+
"[{} {}",
300316
humantime::format_rfc3339_seconds(SystemTime::now()),
301317
level,
302-
if self.include_session_id {
303-
format!(" {}", self.custom_fields.session_id)
304-
} else {
305-
String::new()
306-
},
307-
target,
308-
message
309-
)
318+
)?;
319+
320+
if self.include_session_id {
321+
write!(writer, " {}", self.session_id)?;
322+
}
323+
324+
write!(writer, " - {}] ", target)?;
325+
326+
// Write message directly without intermediate String
327+
let mut visitor = DirectWriteVisitor { writer };
328+
event.record(&mut visitor);
329+
330+
writeln!(writer)
310331
}
332+
}
333+
334+
/// JSON formatter matching fern's JSON format exactly
335+
#[derive(Clone)]
336+
struct JsonFormatter {
337+
include_session_id: bool,
338+
session_id: String,
339+
}
311340

312-
fn format_json(&self, level: &Level, target: &str, message: &str) -> String {
313-
// Match current fern JSON format exactly
314-
let mut log_json = serde_json::json!({
341+
impl JsonFormatter {
342+
fn new(include_session_id: bool, session_id: String) -> Self {
343+
Self {
344+
include_session_id,
345+
session_id,
346+
}
347+
}
348+
}
349+
350+
impl LegacyFormatter for JsonFormatter {
351+
#[inline]
352+
fn write_event<W: Write>(
353+
&self,
354+
writer: &mut W,
355+
level: &Level,
356+
target: &str,
357+
event: &Event<'_>,
358+
) -> std::io::Result<()> {
359+
// Extract message first since it appears in the middle of the JSON object
360+
let mut message_visitor = MessageVisitor::default();
361+
event.record(&mut message_visitor);
362+
363+
// Build JSON object - serde_json handles escaping correctly
364+
let mut log_entry = serde_json::json!({
315365
"timestamp": chrono::Utc::now().to_rfc3339(),
316366
"severity": level.to_string(),
317367
"target": target,
318-
"message": message,
368+
"message": message_visitor.message,
319369
});
320370

321371
if self.include_session_id {
322-
log_json["session_id"] =
323-
serde_json::Value::String(self.custom_fields.session_id.clone());
372+
log_entry["session_id"] = serde_json::Value::String(self.session_id.clone());
324373
}
325374

326-
serde_json::to_string(&log_json)
327-
.expect("formatting `serde_json::Value` with string keys never fails")
375+
serde_json::to_writer(&mut *writer, &log_entry).map_err(std::io::Error::other)?;
376+
writeln!(writer)
328377
}
329378
}
330379

331-
impl<S, W> Layer<S> for LegacyFormatLayer<W>
380+
/// Layer that formats logs to match the legacy fern format exactly.
381+
///
382+
/// Generic over the formatter type `F`, enabling monomorphization so the
383+
/// compiler can inline the format logic directly into `on_event`.
384+
struct LegacyFormatLayer<W, F> {
385+
writer: W,
386+
formatter: F,
387+
}
388+
389+
impl<W, F> LegacyFormatLayer<W, F> {
390+
fn new(writer: W, formatter: F) -> Self {
391+
Self { writer, formatter }
392+
}
393+
}
394+
395+
impl<S, W, F> Layer<S> for LegacyFormatLayer<W, F>
332396
where
333397
S: Subscriber + for<'a> LookupSpan<'a>,
334398
W: for<'writer> MakeWriter<'writer> + 'static,
399+
F: LegacyFormatter + 'static,
335400
{
336401
fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
337-
// Extract metadata
338402
let metadata = event.metadata();
339-
let level = metadata.level();
340-
let target = metadata.target();
403+
let mut writer = self.writer.make_writer();
341404

342-
// Extract message using visitor
343-
let mut visitor = MessageVisitor::default();
344-
event.record(&mut visitor);
345-
let message = visitor.message;
405+
// Write directly to output, avoiding intermediate allocations
406+
let _ = self
407+
.formatter
408+
.write_event(&mut writer, metadata.level(), metadata.target(), event);
409+
}
410+
}
346411

347-
// Format based on LogFormat
348-
let output = if self.format == LogFormat::Text {
349-
self.format_text(level, target, &message)
350-
} else {
351-
self.format_json(level, target, &message)
352-
};
412+
/// Visitor that writes the message field directly to a writer, avoiding intermediate allocation.
413+
///
414+
/// For string messages (the common case), writes directly without any allocation.
415+
/// For debug-formatted messages, uses a small stack buffer to strip surrounding quotes.
416+
struct DirectWriteVisitor<'a, W> {
417+
writer: &'a mut W,
418+
}
353419

354-
// Write to output
355-
let mut writer = self.writer.make_writer();
356-
let _ = writer.write_all(output.as_bytes());
357-
let _ = writer.write_all(b"\n");
420+
impl<W: Write> Visit for DirectWriteVisitor<'_, W> {
421+
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
422+
if field.name() == "message" {
423+
let _ = write!(self.writer, "{:?}", value);
424+
}
425+
}
426+
427+
fn record_str(&mut self, field: &Field, value: &str) {
428+
if field.name() == "message" {
429+
let _ = self.writer.write_all(value.as_bytes());
430+
}
358431
}
359432
}
360433

434+
/// Visitor that extracts the message into a String (used for JSON where we need the value mid-output).
361435
#[derive(Default)]
362436
struct MessageVisitor {
363437
message: String,
@@ -367,10 +441,12 @@ impl Visit for MessageVisitor {
367441
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
368442
if field.name() == "message" {
369443
self.message = format!("{:?}", value);
370-
// Remove surrounding quotes from debug format
371-
if self.message.starts_with('"') && self.message.ends_with('"') {
372-
self.message = self.message[1..self.message.len() - 1].to_string();
373-
}
444+
}
445+
}
446+
447+
fn record_str(&mut self, field: &Field, value: &str) {
448+
if field.name() == "message" {
449+
self.message = value.to_string();
374450
}
375451
}
376452
}
@@ -594,64 +670,96 @@ fn setup_modern_format(
594670

595671
fn setup_legacy_format(
596672
settings: &LoggerSettings,
597-
_session_id: &str,
598-
_machine_id: &str,
673+
session_id: &str,
674+
machine_id: &str,
599675
custom_fields: CustomFields,
600676
) -> Result<(), LoggerError> {
601677
let env_filter = EnvFilter::try_from_default_env()
602678
.unwrap_or_else(|_| EnvFilter::new(settings.level.to_tracing_level().to_string()));
603679

604-
// Setup with or without OTEL based on configuration
605-
if let Some(_endpoint) = &settings.export_to {
606-
if settings.stdout {
607-
let legacy_layer = LegacyFormatLayer::new(
608-
std::io::stdout,
609-
settings.format.clone(),
610-
settings.include_session_id,
611-
custom_fields,
612-
);
613-
680+
// Branch on format type at setup time to get monomorphized Layer implementations.
681+
// Each branch creates a concrete formatter type, enabling the compiler to inline
682+
// the format logic directly into on_event.
683+
match (&settings.format, &settings.export_to, settings.stdout) {
684+
(LogFormat::Text, Some(endpoint), true) => {
685+
let formatter =
686+
TextFormatter::new(settings.include_session_id, custom_fields.session_id);
687+
let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?;
688+
let legacy_layer = LegacyFormatLayer::new(std::io::stdout, formatter);
614689
tracing_subscriber::registry()
690+
.with(otel_layer)
615691
.with(env_filter)
616692
.with(legacy_layer)
617693
.init();
618-
} else {
694+
}
695+
(LogFormat::Text, Some(endpoint), false) => {
696+
let formatter =
697+
TextFormatter::new(settings.include_session_id, custom_fields.session_id);
698+
let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?;
619699
let file_appender = create_rolling_file_appender(&settings.log_file_date_format);
620-
let legacy_layer = LegacyFormatLayer::new(
621-
file_appender,
622-
settings.format.clone(),
623-
settings.include_session_id,
624-
custom_fields,
625-
);
626-
700+
let legacy_layer = LegacyFormatLayer::new(file_appender, formatter);
627701
tracing_subscriber::registry()
702+
.with(otel_layer)
628703
.with(env_filter)
629704
.with(legacy_layer)
630705
.init();
631706
}
632-
} else {
633-
// No OTEL export
634-
if settings.stdout {
635-
let legacy_layer = LegacyFormatLayer::new(
636-
std::io::stdout,
637-
settings.format.clone(),
638-
settings.include_session_id,
639-
custom_fields.clone(),
640-
);
641-
707+
(LogFormat::Text, None, true) => {
708+
let formatter =
709+
TextFormatter::new(settings.include_session_id, custom_fields.session_id);
710+
let legacy_layer = LegacyFormatLayer::new(std::io::stdout, formatter);
642711
tracing_subscriber::registry()
643712
.with(env_filter)
644713
.with(legacy_layer)
645714
.init();
646-
} else {
715+
}
716+
(LogFormat::Text, None, false) => {
717+
let formatter =
718+
TextFormatter::new(settings.include_session_id, custom_fields.session_id);
647719
let file_appender = create_rolling_file_appender(&settings.log_file_date_format);
648-
let legacy_layer = LegacyFormatLayer::new(
649-
file_appender,
650-
settings.format.clone(),
651-
settings.include_session_id,
652-
custom_fields,
653-
);
654-
720+
let legacy_layer = LegacyFormatLayer::new(file_appender, formatter);
721+
tracing_subscriber::registry()
722+
.with(env_filter)
723+
.with(legacy_layer)
724+
.init();
725+
}
726+
(LogFormat::Json, Some(endpoint), true) => {
727+
let formatter =
728+
JsonFormatter::new(settings.include_session_id, custom_fields.session_id);
729+
let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?;
730+
let legacy_layer = LegacyFormatLayer::new(std::io::stdout, formatter);
731+
tracing_subscriber::registry()
732+
.with(otel_layer)
733+
.with(env_filter)
734+
.with(legacy_layer)
735+
.init();
736+
}
737+
(LogFormat::Json, Some(endpoint), false) => {
738+
let formatter =
739+
JsonFormatter::new(settings.include_session_id, custom_fields.session_id);
740+
let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?;
741+
let file_appender = create_rolling_file_appender(&settings.log_file_date_format);
742+
let legacy_layer = LegacyFormatLayer::new(file_appender, formatter);
743+
tracing_subscriber::registry()
744+
.with(otel_layer)
745+
.with(env_filter)
746+
.with(legacy_layer)
747+
.init();
748+
}
749+
(LogFormat::Json, None, true) => {
750+
let formatter =
751+
JsonFormatter::new(settings.include_session_id, custom_fields.session_id);
752+
let legacy_layer = LegacyFormatLayer::new(std::io::stdout, formatter);
753+
tracing_subscriber::registry()
754+
.with(env_filter)
755+
.with(legacy_layer)
756+
.init();
757+
}
758+
(LogFormat::Json, None, false) => {
759+
let formatter =
760+
JsonFormatter::new(settings.include_session_id, custom_fields.session_id);
761+
let file_appender = create_rolling_file_appender(&settings.log_file_date_format);
762+
let legacy_layer = LegacyFormatLayer::new(file_appender, formatter);
655763
tracing_subscriber::registry()
656764
.with(env_filter)
657765
.with(legacy_layer)

0 commit comments

Comments
 (0)