moved http client tracer to api/client. added tracing on uploads

cmd/swarm/swarm-smoke/feed_upload_and_sync.go

@@ -19,6 +19,7 @@ import (
 	"github.com/ethereum/go-ethereum/crypto"
 	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/metrics"
+	"github.com/ethereum/go-ethereum/swarm/api/client"
 	"github.com/ethereum/go-ethereum/swarm/spancontext"
 	"github.com/ethereum/go-ethereum/swarm/storage/feed"
 	"github.com/ethereum/go-ethereum/swarm/testutil"
@@ -325,7 +326,7 @@ func fetchFeed(topic string, user string, endpoint string, original []byte, ruid
 		opentracing.HTTPHeaders,
 		opentracing.HTTPHeadersCarrier(req.Header))
 
-	trace := getClientTrace("feed-and-sync", ruid, &tn)
+	trace := client.GetClientTrace("feed-and-sync - http get", "feed-and-sync", ruid, &tn)
 
 	req = req.WithContext(httptrace.WithClientTrace(ctx, trace))
 	transport := http.DefaultTransport

cmd/swarm/swarm-smoke/main.go

@@ -18,10 +18,8 @@ package main
 
 import (
 	"fmt"
-	"net/http/httptrace"
 	"os"
 	"sort"
-	"time"
 
 	"github.com/ethereum/go-ethereum/cmd/utils"
 	gethmetrics "github.com/ethereum/go-ethereum/metrics"
@@ -190,57 +188,3 @@ func emitMetrics(ctx *cli.Context) error {
 
 	return nil
 }
-
-func getClientTrace(testName, ruid string, tn *time.Time) *httptrace.ClientTrace {
-	trace := &httptrace.ClientTrace{
-		GetConn: func(_ string) {
-			log.Trace(testName+" - http get", "event", "GetConn", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.getconn", nil).Update(time.Since(*tn))
-		},
-		GotConn: func(_ httptrace.GotConnInfo) {
-			log.Trace(testName+" - http get", "event", "GotConn", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.gotconn", nil).Update(time.Since(*tn))
-		},
-		PutIdleConn: func(err error) {
-			log.Trace(testName+" - http get", "event", "PutIdleConn", "ruid", ruid, "err", err)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.putidle", nil).Update(time.Since(*tn))
-		},
-		GotFirstResponseByte: func() {
-			log.Trace(testName+" - http get", "event", "GotFirstResponseByte", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.firstbyte", nil).Update(time.Since(*tn))
-		},
-		Got100Continue: func() {
-			log.Trace(testName+" - http get", "event", "Got100Continue", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.got100continue", nil).Update(time.Since(*tn))
-		},
-		DNSStart: func(_ httptrace.DNSStartInfo) {
-			log.Trace(testName+" - http get", "event", "DNSStart", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.dnsstart", nil).Update(time.Since(*tn))
-		},
-		DNSDone: func(_ httptrace.DNSDoneInfo) {
-			log.Trace(testName+" - http get", "event", "DNSDone", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.dnsdone", nil).Update(time.Since(*tn))
-		},
-		ConnectStart: func(network, addr string) {
-			log.Trace(testName+" - http get", "event", "ConnectStart", "ruid", ruid, "network", network, "addr", addr)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.connectstart", nil).Update(time.Since(*tn))
-		},
-		ConnectDone: func(network, addr string, err error) {
-			log.Trace(testName+" - http get", "event", "ConnectDone", "ruid", ruid, "network", network, "addr", addr, "err", err)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.connectdone", nil).Update(time.Since(*tn))
-		},
-		WroteHeaders: func() {
-			log.Trace(testName+" - http get", "event", "WroteHeaders(request)", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.wroteheaders", nil).Update(time.Since(*tn))
-		},
-		Wait100Continue: func() {
-			log.Trace(testName+" - http get", "event", "Wait100Continue", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.wait100continue", nil).Update(time.Since(*tn))
-		},
-		WroteRequest: func(_ httptrace.WroteRequestInfo) {
-			log.Trace(testName+" - http get", "event", "WroteRequest", "ruid", ruid)
-			gethmetrics.GetOrRegisterResettingTimer(testName+".fetch.clienttrace.wroterequest", nil).Update(time.Since(*tn))
-		},
-	}
-	return trace
-}

cmd/swarm/swarm-smoke/upload_and_sync.go

@@ -173,7 +173,7 @@ func fetch(hash string, endpoint string, original []byte, ruid string) error {
 		opentracing.HTTPHeaders,
 		opentracing.HTTPHeadersCarrier(req.Header))
 
-	trace := getClientTrace("upload-and-sync", ruid, &tn)
+	trace := client.GetClientTrace("upload-and-sync - http get", "upload-and-sync", ruid, &tn)
 
 	req = req.WithContext(httptrace.WithClientTrace(ctx, trace))
 	transport := http.DefaultTransport

swarm/api/client/client.go

@@ -19,6 +19,7 @@ package client
 import (
 	"archive/tar"
 	"bytes"
+	"context"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -26,6 +27,7 @@ import (
 	"io/ioutil"
 	"mime/multipart"
 	"net/http"
+	"net/http/httptrace"
 	"net/textproto"
 	"net/url"
 	"os"
@@ -33,9 +35,15 @@ import (
 	"regexp"
 	"strconv"
 	"strings"
+	"time"
 
+	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 	"github.com/ethereum/go-ethereum/swarm/api"
+	"github.com/ethereum/go-ethereum/swarm/spancontext"
 	"github.com/ethereum/go-ethereum/swarm/storage/feed"
+	opentracing "github.com/opentracing/opentracing-go"
+	"github.com/pborman/uuid"
 )
 
 var (
@@ -474,6 +482,11 @@ type UploadFn func(file *File) error
 // TarUpload uses the given Uploader to upload files to swarm as a tar stream,
 // returning the resulting manifest hash
 func (c *Client) TarUpload(hash string, uploader Uploader, defaultPath string, toEncrypt bool) (string, error) {
+	ctx, sp := spancontext.StartSpan(context.Background(), "swarm.api.client.tarupload")
+	defer sp.Finish()
+
+	var tn time.Time
+
 	reqR, reqW := io.Pipe()
 	defer reqR.Close()
 	addr := hash
@@ -489,6 +502,17 @@ func (c *Client) TarUpload(hash string, uploader Uploader, defaultPath string, t
 	if err != nil {
 		return "", err
 	}
+
+	opentracing.GlobalTracer().Inject(
+		sp.Context(),
+		opentracing.HTTPHeaders,
+		opentracing.HTTPHeadersCarrier(req.Header))
+
+	trace := GetClientTrace("swarm api client - upload tar", "swarm.api.client.uploadtar", uuid.New()[:8], &tn)
+
+	req = req.WithContext(httptrace.WithClientTrace(ctx, trace))
+	transport := http.DefaultTransport
+
 	req.Header.Set("Content-Type", "application/x-tar")
 	if defaultPath != "" {
 		q := req.URL.Query()
@@ -529,8 +553,8 @@ func (c *Client) TarUpload(hash string, uploader Uploader, defaultPath string, t
 		}
 		reqW.CloseWithError(err)
 	}()
-
-	res, err := http.DefaultClient.Do(req)
+	tn = time.Now()
+	res, err := transport.RoundTrip(req)
 	if err != nil {
 		return "", err
 	}
@@ -728,3 +752,57 @@ func (c *Client) GetFeedRequest(query *feed.Query, manifestAddressOrDomain strin
 	}
 	return &metadata, nil
 }
+
+func GetClientTrace(traceMsg, metricPrefix, ruid string, tn *time.Time) *httptrace.ClientTrace {
+	trace := &httptrace.ClientTrace{
+		GetConn: func(_ string) {
+			log.Trace(traceMsg+" - http get", "event", "GetConn", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.getconn", nil).Update(time.Since(*tn))
+		},
+		GotConn: func(_ httptrace.GotConnInfo) {
+			log.Trace(traceMsg+" - http get", "event", "GotConn", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.gotconn", nil).Update(time.Since(*tn))
+		},
+		PutIdleConn: func(err error) {
+			log.Trace(traceMsg+" - http get", "event", "PutIdleConn", "ruid", ruid, "err", err)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.putidle", nil).Update(time.Since(*tn))
+		},
+		GotFirstResponseByte: func() {
+			log.Trace(traceMsg+" - http get", "event", "GotFirstResponseByte", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.firstbyte", nil).Update(time.Since(*tn))
+		},
+		Got100Continue: func() {
+			log.Trace(traceMsg, "event", "Got100Continue", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.got100continue", nil).Update(time.Since(*tn))
+		},
+		DNSStart: func(_ httptrace.DNSStartInfo) {
+			log.Trace(traceMsg, "event", "DNSStart", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.dnsstart", nil).Update(time.Since(*tn))
+		},
+		DNSDone: func(_ httptrace.DNSDoneInfo) {
+			log.Trace(traceMsg, "event", "DNSDone", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.dnsdone", nil).Update(time.Since(*tn))
+		},
+		ConnectStart: func(network, addr string) {
+			log.Trace(traceMsg, "event", "ConnectStart", "ruid", ruid, "network", network, "addr", addr)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.connectstart", nil).Update(time.Since(*tn))
+		},
+		ConnectDone: func(network, addr string, err error) {
+			log.Trace(traceMsg, "event", "ConnectDone", "ruid", ruid, "network", network, "addr", addr, "err", err)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.connectdone", nil).Update(time.Since(*tn))
+		},
+		WroteHeaders: func() {
+			log.Trace(traceMsg, "event", "WroteHeaders(request)", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.wroteheaders", nil).Update(time.Since(*tn))
+		},
+		Wait100Continue: func() {
+			log.Trace(traceMsg, "event", "Wait100Continue", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.wait100continue", nil).Update(time.Since(*tn))
+		},
+		WroteRequest: func(_ httptrace.WroteRequestInfo) {
+			log.Trace(traceMsg, "event", "WroteRequest", "ruid", ruid)
+			metrics.GetOrRegisterResettingTimer(metricPrefix+".fetch.clienttrace.wroterequest", nil).Update(time.Since(*tn))
+		},
+	}
+	return trace
+}