diff --git a/plugins/inputs/opcua/opcua.go b/plugins/inputs/opcua/opcua.go index bbbf9f1b649e1..63a2a2a91a60b 100644 --- a/plugins/inputs/opcua/opcua.go +++ b/plugins/inputs/opcua/opcua.go @@ -35,6 +35,9 @@ func (o *OpcUA) Init() (err error) { } func (o *OpcUA) Gather(acc telegraf.Accumulator) error { + gatherStart := time.Now() + o.Log.Tracef("Gather starting for %d nodes...", len(o.client.NodeIDs)) + // Force reconnection every time if a threshold is 0 if o.client.ReconnectErrorThreshold == 0 { o.client.forceReconnect = true @@ -44,6 +47,8 @@ func (o *OpcUA) Gather(acc telegraf.Accumulator) error { metrics, err := o.client.currentValues() if err != nil { o.consecutiveErrors++ + o.Log.Tracef("Gather failed after %s: %v (consecutive errors: %d)", + time.Since(gatherStart), err, o.consecutiveErrors) // Force reconnection based on an error threshold: if threshold > 0, reconnect after // reaching the specified number of consecutive errors; if a threshold = 0, we already @@ -57,10 +62,13 @@ func (o *OpcUA) Gather(acc telegraf.Accumulator) error { // Reset error counter on success o.consecutiveErrors = 0 + addStart := time.Now() // Parse the resulting data into metrics for _, m := range metrics { acc.AddMetric(m) } + o.Log.Tracef("Gather complete: %d metrics added to accumulator in %s, total gather time %s", + len(metrics), time.Since(addStart), time.Since(gatherStart)) return nil } diff --git a/plugins/inputs/opcua/read_client.go b/plugins/inputs/opcua/read_client.go index f751be3ebf85e..8c3d6ebd18a70 100644 --- a/plugins/inputs/opcua/read_client.go +++ b/plugins/inputs/opcua/read_client.go @@ -118,6 +118,11 @@ func (o *readClient) connect() error { } } + o.Log.Tracef("Node request order (%d nodes):", len(o.reqIDs)) + for i, req := range o.reqIDs { + o.Log.Tracef(" [%d] %s", i, req.NodeID.String()) + } + if err := o.read(); err != nil { return fmt.Errorf("get data failed: %w", err) } @@ -141,15 +146,19 @@ func (o *readClient) ensureConnected() error { } func (o *readClient) currentValues() ([]telegraf.Metric, error) { + connectStart := time.Now() if err := o.ensureConnected(); err != nil { return nil, err } + o.Log.Tracef("Connection check took %s", time.Since(connectStart)) if state := o.State(); state != opcua.Connected { return nil, fmt.Errorf("not connected, in state %q", state) } + readStart := time.Now() if err := o.read(); err != nil { + o.Log.Tracef("Read failed after %s: %v", time.Since(readStart), err) // We do not return the disconnect error, as this would mask the // original problem, but we do log it if derr := o.Disconnect(context.Background()); derr != nil { @@ -158,16 +167,22 @@ func (o *readClient) currentValues() ([]telegraf.Metric, error) { return nil, err } + o.Log.Tracef("OPC UA read of %d nodes took %s", len(o.NodeIDs), time.Since(readStart)) + metricStart := time.Now() metrics := make([]telegraf.Metric, 0, len(o.NodeMetricMapping)) + var skipped int // Parse the resulting data into metrics for i := range o.NodeIDs { if !o.StatusCodeOK(o.LastReceivedData[i].Quality) { + skipped++ continue } metrics = append(metrics, o.MetricForNode(i)) } + o.Log.Tracef("Metric construction took %s (%d metrics, %d skipped due to bad quality)", + time.Since(metricStart), len(metrics), skipped) return metrics, nil } @@ -185,18 +200,26 @@ func (o *readClient) read() error { count++ // Try to update the values for all registered nodes + o.Log.Tracef("Sending OPC UA read request for %d %s nodes (attempt %d)...", + len(o.reqIDs), nodeTypeLabel(o.Workarounds.UseUnregisteredReads), count) + requestStart := time.Now() resp, err := o.Client.Read(o.ctx, req) + plcDuration := time.Since(requestStart) if err == nil { // Success, update the node values and exit o.ReadSuccess.Incr(1) o.forceReconnect = false + o.Log.Tracef("OPC UA read response received in %s, updating %d node values...", plcDuration, len(resp.Results)) + updateStart := time.Now() for i, d := range resp.Results { o.UpdateNodeValue(i, d) } + o.Log.Tracef("Node value update took %s", time.Since(updateStart)) return nil } o.ReadError.Incr(1) + o.Log.Tracef("OPC UA read request failed after %s: %v", plcDuration, err) isSessionError := errors.Is(err, ua.StatusBadSessionIDInvalid) || errors.Is(err, ua.StatusBadSessionNotActivated) ||