Skip to content

Commit

Permalink
piggyback log events on transactions to pool their priorities
Browse files Browse the repository at this point in the history
  • Loading branch information
iamemilio committed Jun 17, 2022
1 parent 0901501 commit f3b5b5b
Show file tree
Hide file tree
Showing 5 changed files with 54 additions and 31 deletions.
32 changes: 17 additions & 15 deletions v3/examples/server/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -252,7 +252,6 @@ func main() {
newrelic.ConfigAppName("Example App"),
newrelic.ConfigFromEnvironment(),
newrelic.ConfigDebugLogger(os.Stdout),
newrelic.ConfigDistributedTracerEnabled(true),
newrelic.ConfigAppLogForwardingEnabled(true),
)
if err != nil {
Expand All @@ -278,28 +277,31 @@ func main() {
http.HandleFunc(newrelic.WrapHandleFunc(app, "/async", async))
http.HandleFunc(newrelic.WrapHandleFunc(app, "/message", message))
http.HandleFunc("/log", func(w http.ResponseWriter, req *http.Request) {
// Transactions started without an http.Request are classified as
// background transactions.
txn := app.StartTransaction("Log")
defer txn.End()

ctx := newrelic.NewContext(context.Background(), txn)

// Versions of go prior to 1.17 do not have a built in function for Unix Milli time.
// For go versions 1.17+ use time.Now().UnixMilli() to generate timestamps
timestamp := time.Now().UnixNano() / int64(time.Millisecond)

data := newrelic.LogData{
app.RecordLog(newrelic.LogData{
Timestamp: timestamp,
Message: "Log Message",
Severity: "info",
Context: ctx,
}
})

app.RecordLog(data)
io.WriteString(w, "A log message was recorded")
})

io.WriteString(w, "Log")
time.Sleep(150 * time.Millisecond)
http.HandleFunc("/transaction_log", func(w http.ResponseWriter, req *http.Request) {
txn := app.StartTransaction("Log Transaction")
defer txn.End()
ctx := newrelic.NewContext(context.Background(), txn)

app.RecordLog(newrelic.LogData{
Timestamp: time.Now().UnixNano() / int64(time.Millisecond),
Message: "Transaction Log Message",
Severity: "info",
Context: ctx,
})

io.WriteString(w, "A log message was recorded as part of a transaction")
})

http.HandleFunc("/background", func(w http.ResponseWriter, req *http.Request) {
Expand Down
18 changes: 16 additions & 2 deletions v3/newrelic/internal_app.go
Original file line number Diff line number Diff line change
Expand Up @@ -596,8 +596,22 @@ func (app *app) RecordLog(log *LogData) error {
return err
}

run, _ := app.getState()
app.Consume(run.Reply.RunID, &event)
var txn *Transaction
if log.Context != nil {
txn = FromContext(log.Context)
}

// Whenever a log is part of a transaction, store it on the transaction
// to ensure it gets correctly prioritized.
if txn != nil {
metadata := txn.GetTraceMetadata()
event.spanID = metadata.SpanID
event.traceID = metadata.SpanID
txn.thread.StoreLog(&event)
} else {
run, _ := app.getState()
app.Consume(run.Reply.RunID, &event)
}
return nil
}

Expand Down
20 changes: 20 additions & 0 deletions v3/newrelic/internal_txn.go
Original file line number Diff line number Diff line change
Expand Up @@ -226,6 +226,19 @@ func (thd *thread) SetWebResponse(w http.ResponseWriter) http.ResponseWriter {
})
}

func (thd *thread) StoreLog(log *logEvent) {
txn := thd.txn
txn.Lock()
defer txn.Unlock()

// Copy log data into the slice so that the stack frame can return without needing to allocate heap memory
if txn.logs == nil {
txn.logs = []logEvent{*log}
} else {
txn.logs = append(txn.logs, *log)
}
}

func (txn *txn) freezeName() {
if txn.ignore || ("" != txn.FinalName) {
return
Expand Down Expand Up @@ -262,6 +275,13 @@ func (txn *txn) MergeIntoHarvest(h *harvest) {
createTxnMetrics(&txn.txnData, h.Metrics)
mergeBreakdownMetrics(&txn.txnData, h.Metrics)

// Dump log events into harvest
// Note: this will create a surge of log events that could affect sampling.
for _, logEvent := range txn.logs {
logEvent.priority = priority
h.LogEvents.Add(&logEvent)
}

if txn.Config.TransactionEvents.Enabled {
// Allocate a new TxnEvent to prevent a reference to the large transaction.
alloc := new(txnEvent)
Expand Down
14 changes: 0 additions & 14 deletions v3/newrelic/log_event.go
Original file line number Diff line number Diff line change
Expand Up @@ -108,24 +108,10 @@ func (data *LogData) toLogEvent() (logEvent, error) {
data.Message = strings.TrimSpace(data.Message)
data.Severity = strings.TrimSpace(data.Severity)

var spanID, traceID string
var priority priority

if data.Context != nil {
txn := FromContext(data.Context)
priority = txn.thread.BetterCAT.Priority
traceMetadata := txn.GetTraceMetadata()
spanID = traceMetadata.SpanID
traceID = traceMetadata.TraceID
}

event := logEvent{
message: data.Message,
severity: data.Severity,
spanID: spanID,
traceID: traceID,
timestamp: data.Timestamp,
priority: priority,
}

return event, nil
Expand Down
1 change: 1 addition & 0 deletions v3/newrelic/tracing.go
Original file line number Diff line number Diff line change
Expand Up @@ -79,6 +79,7 @@ type txnData struct {
rootSpanID string
rootSpanErrData *errorData
SpanEvents []*spanEvent
logs []logEvent

customSegments map[string]*metricData
datastoreSegments map[datastoreMetricKey]*metricData
Expand Down

0 comments on commit f3b5b5b

Please sign in to comment.