Replace string concatination with trace fields

This commit is contained in:
Joe Betz 2019-08-02 23:47:24 -07:00
parent 31799ebe88
commit 46a04d50af
14 changed files with 48 additions and 28 deletions

View File

@ -187,7 +187,7 @@ func (g *genericScheduler) snapshot() error {
// If it succeeds, it will return the name of the node.
// If it fails, it will return a FitError error with reasons.
func (g *genericScheduler) Schedule(pod *v1.Pod, nodeLister algorithm.NodeLister, pluginContext *framework.PluginContext) (result ScheduleResult, err error) {
trace := utiltrace.New(fmt.Sprintf("Scheduling %s/%s", pod.Namespace, pod.Name))
trace := utiltrace.New("Scheduling", utiltrace.Field{Key: "namespace", Value: pod.Namespace}, utiltrace.Field{Key: "name", Value: pod.Name})
defer trace.LogIfLong(100 * time.Millisecond)
if err := podPassesBasicChecks(pod, g.pvcLister); err != nil {

View File

@ -182,9 +182,11 @@ func (c *webhookConverter) Convert(in runtime.Object, toGV schema.GroupVersion)
return out, nil
}
trace := utiltrace.New(fmt.Sprintf(
"Call conversion webhook: custom resource definition: %s, desired API version: %s, object count: %d, UID: %v",
c.name, request.Request.DesiredAPIVersion, objCount, request.Request.UID))
trace := utiltrace.New("Call conversion webhook",
utiltrace.Field{"custom-resource-definition", c.name},
utiltrace.Field{"desired-api-version", request.Request.DesiredAPIVersion},
utiltrace.Field{"object-count", objCount},
utiltrace.Field{"UID", request.Request.UID})
// Only log conversion webhook traces that exceed a 8ms per object limit plus a 50ms request overhead allowance.
// The per object limit uses the SLO for conversion webhooks (~4ms per object) plus time to serialize/deserialize
// the conversion request on the apiserver side (~4ms per object).

View File

@ -173,10 +173,14 @@ func (a *mutatingDispatcher) callAttrMutatingHook(ctx context.Context, h *v1beta
if err != nil {
return false, &webhookutil.ErrCallingWebhook{WebhookName: h.Name, Reason: err}
}
trace := utiltrace.New(fmt.Sprintf("Call mutating webhook: configuration: %s, webhook: %s, resource: %v, subResource: %s, operation: %v, UID: %v",
invocation.Webhook.GetConfigurationName(), h.Name, request.Request.Resource, request.Request.SubResource, request.Request.Operation, request.Request.UID))
trace := utiltrace.New("Call mutating webhook",
utiltrace.Field{"configuration", invocation.Webhook.GetConfigurationName()},
utiltrace.Field{"webhook", h.Name},
utiltrace.Field{"resource", attr.GetResource()},
utiltrace.Field{"subresource", attr.GetSubresource()},
utiltrace.Field{"operation", attr.GetOperation()},
utiltrace.Field{"UID", uid})
defer trace.LogIfLong(500 * time.Millisecond)
response := &admissionv1beta1.AdmissionReview{}
r := client.Post().Context(ctx).Body(request)
if h.TimeoutSeconds != nil {
r = r.Timeout(time.Duration(*h.TimeoutSeconds) * time.Second)

View File

@ -154,10 +154,14 @@ func (d *validatingDispatcher) callHook(ctx context.Context, h *v1beta1.Validati
if err != nil {
return &webhookutil.ErrCallingWebhook{WebhookName: h.Name, Reason: err}
}
trace := utiltrace.New(fmt.Sprintf("Call validating webhook: configuration: %s, webhook: %s, resource: %v, subResource: %s, operation: %v, UID: %v",
invocation.Webhook.GetConfigurationName(), h.Name, request.Request.Resource, request.Request.SubResource, request.Request.Operation, request.Request.UID))
trace := utiltrace.New("Call validating webhook",
utiltrace.Field{"configuration", invocation.Webhook.GetConfigurationName()},
utiltrace.Field{"webhook", h.Name},
utiltrace.Field{"resource", attr.GetResource()},
utiltrace.Field{"subresource", attr.GetSubresource()},
utiltrace.Field{"operation", attr.GetOperation()},
utiltrace.Field{"UID", uid})
defer trace.LogIfLong(500 * time.Millisecond)
response := &admissionv1beta1.AdmissionReview{}
r := client.Post().Context(ctx).Body(request)
if h.TimeoutSeconds != nil {
r = r.Timeout(time.Duration(*h.TimeoutSeconds) * time.Second)

View File

@ -46,7 +46,7 @@ import (
func createHandler(r rest.NamedCreater, scope *RequestScope, admit admission.Interface, includeName bool) http.HandlerFunc {
return func(w http.ResponseWriter, req *http.Request) {
// For performance tracking purposes.
trace := utiltrace.New("Create " + req.URL.Path)
trace := utiltrace.New("Create", utiltrace.Field{"url", req.URL.Path})
defer trace.LogIfLong(500 * time.Millisecond)
if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {

View File

@ -43,7 +43,7 @@ import (
func DeleteResource(r rest.GracefulDeleter, allowsOptions bool, scope *RequestScope, admit admission.Interface) http.HandlerFunc {
return func(w http.ResponseWriter, req *http.Request) {
// For performance tracking purposes.
trace := utiltrace.New("Delete " + req.URL.Path)
trace := utiltrace.New("Delete", utiltrace.Field{"url", req.URL.Path})
defer trace.LogIfLong(500 * time.Millisecond)
if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {
@ -160,7 +160,7 @@ func DeleteResource(r rest.GracefulDeleter, allowsOptions bool, scope *RequestSc
// DeleteCollection returns a function that will handle a collection deletion
func DeleteCollection(r rest.CollectionDeleter, checkBody bool, scope *RequestScope, admit admission.Interface) http.HandlerFunc {
return func(w http.ResponseWriter, req *http.Request) {
trace := utiltrace.New("Delete " + req.URL.Path)
trace := utiltrace.New("Delete", utiltrace.Field{"url", req.URL.Path})
defer trace.LogIfLong(500 * time.Millisecond)
if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {

View File

@ -48,7 +48,7 @@ type getterFunc func(ctx context.Context, name string, req *http.Request, trace
// passed-in getterFunc to perform the actual get.
func getResourceHandler(scope *RequestScope, getter getterFunc) http.HandlerFunc {
return func(w http.ResponseWriter, req *http.Request) {
trace := utiltrace.New("Get " + req.URL.Path)
trace := utiltrace.New("Get", utiltrace.Field{"url", req.URL.Path})
defer trace.LogIfLong(500 * time.Millisecond)
namespace, name, err := scope.Namer.Name(req)
@ -165,7 +165,7 @@ func getRequestOptions(req *http.Request, scope *RequestScope, into runtime.Obje
func ListResource(r rest.Lister, rw rest.Watcher, scope *RequestScope, forceWatch bool, minRequestTimeout time.Duration) http.HandlerFunc {
return func(w http.ResponseWriter, req *http.Request) {
// For performance tracking purposes.
trace := utiltrace.New("List " + req.URL.Path)
trace := utiltrace.New("List", utiltrace.Field{"url", req.URL.Path})
namespace, err := scope.Namer.Namespace(req)
if err != nil {
@ -273,6 +273,6 @@ func ListResource(r rest.Lister, rw rest.Watcher, scope *RequestScope, forceWatc
trace.Step("Listing from storage done")
transformResponseObject(ctx, scope, trace, req, w, http.StatusOK, outputMediaType, result)
trace.Step(fmt.Sprintf("Writing http response done (%d items)", meta.LenList(result)))
trace.Step("Writing http response done", utiltrace.Field{"count", meta.LenList(result)})
}
}

View File

@ -59,7 +59,7 @@ const (
func PatchResource(r rest.Patcher, scope *RequestScope, admit admission.Interface, patchTypes []string) http.HandlerFunc {
return func(w http.ResponseWriter, req *http.Request) {
// For performance tracking purposes.
trace := utiltrace.New("Patch " + req.URL.Path)
trace := utiltrace.New("Patch", utiltrace.Field{"url", req.URL.Path})
defer trace.LogIfLong(500 * time.Millisecond)
if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {

View File

@ -463,7 +463,7 @@ func (tc *patchTestCase) Run(t *testing.T) {
patchType: patchType,
patchBytes: patch,
trace: utiltrace.New("Patch" + name),
trace: utiltrace.New("Patch", utiltrace.Field{"name", name}),
}
resultObj, _, err := p.patchResource(ctx, &RequestScope{})

View File

@ -45,7 +45,7 @@ import (
func UpdateResource(r rest.Updater, scope *RequestScope, admit admission.Interface) http.HandlerFunc {
return func(w http.ResponseWriter, req *http.Request) {
// For performance tracking purposes.
trace := utiltrace.New("Update " + req.URL.Path)
trace := utiltrace.New("Update", utiltrace.Field{"url", req.URL.Path})
defer trace.LogIfLong(500 * time.Millisecond)
if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {

View File

@ -604,7 +604,7 @@ func (c *Cacher) GetToList(ctx context.Context, key string, resourceVersion stri
return c.storage.GetToList(ctx, key, resourceVersion, pred, listObj)
}
trace := utiltrace.New(fmt.Sprintf("cacher %v: List", c.objectType.String()))
trace := utiltrace.New("cacher list", utiltrace.Field{"type", c.objectType.String()})
defer trace.LogIfLong(500 * time.Millisecond)
c.ready.wait()
@ -673,7 +673,7 @@ func (c *Cacher) List(ctx context.Context, key string, resourceVersion string, p
return c.storage.List(ctx, key, resourceVersion, pred, listObj)
}
trace := utiltrace.New(fmt.Sprintf("cacher %v: List", c.objectType.String()))
trace := utiltrace.New("cacher list", utiltrace.Field{"type", c.objectType.String()})
defer trace.LogIfLong(500 * time.Millisecond)
c.ready.wait()
@ -694,7 +694,7 @@ func (c *Cacher) List(ctx context.Context, key string, resourceVersion string, p
if err != nil {
return err
}
trace.Step(fmt.Sprintf("Listed %d items from cache", len(objs)))
trace.Step("Listed items from cache", utiltrace.Field{"count", len(objs)})
if len(objs) > listVal.Cap() && pred.Label.Empty() && pred.Field.Empty() {
// Resize the slice appropriately, since we already know that none
// of the elements will be filtered out.
@ -710,7 +710,7 @@ func (c *Cacher) List(ctx context.Context, key string, resourceVersion string, p
listVal.Set(reflect.Append(listVal, reflect.ValueOf(elem.Object).Elem()))
}
}
trace.Step(fmt.Sprintf("Filtered %d items", listVal.Len()))
trace.Step("Filtered items", utiltrace.Field{"count", listVal.Len()})
if c.versioner != nil {
if err := c.versioner.UpdateList(listObj, readResourceVersion, "", nil); err != nil {
return err

View File

@ -236,7 +236,7 @@ func (s *store) conditionalDelete(ctx context.Context, key string, out runtime.O
func (s *store) GuaranteedUpdate(
ctx context.Context, key string, out runtime.Object, ignoreNotFound bool,
preconditions *storage.Preconditions, tryUpdate storage.UpdateFunc, suggestion ...runtime.Object) error {
trace := utiltrace.New(fmt.Sprintf("GuaranteedUpdate etcd3: %s", getTypeName(out)))
trace := utiltrace.New("GuaranteedUpdate etcd3", utiltrace.Field{"type", getTypeName(out)})
defer trace.LogIfLong(500 * time.Millisecond)
v, err := conversion.EnforcePtr(out)
@ -363,7 +363,11 @@ func (s *store) GuaranteedUpdate(
// GetToList implements storage.Interface.GetToList.
func (s *store) GetToList(ctx context.Context, key string, resourceVersion string, pred storage.SelectionPredicate, listObj runtime.Object) error {
trace := utiltrace.New(fmt.Sprintf("GetToList etcd3: key=%v, resourceVersion=%s, limit: %d, continue: %s", key, resourceVersion, pred.Limit, pred.Continue))
trace := utiltrace.New("GetToList etcd3",
utiltrace.Field{"key", key},
utiltrace.Field{"resourceVersion", resourceVersion},
utiltrace.Field{"limit", pred.Limit},
utiltrace.Field{"continue", pred.Continue})
defer trace.LogIfLong(500 * time.Millisecond)
listPtr, err := meta.GetItemsPtr(listObj)
if err != nil {
@ -468,7 +472,11 @@ func encodeContinue(key, keyPrefix string, resourceVersion int64) (string, error
// List implements storage.Interface.List.
func (s *store) List(ctx context.Context, key, resourceVersion string, pred storage.SelectionPredicate, listObj runtime.Object) error {
trace := utiltrace.New(fmt.Sprintf("List etcd3: key=%v, resourceVersion=%s, limit: %d, continue: %s", key, resourceVersion, pred.Limit, pred.Continue))
trace := utiltrace.New("List etcd3",
utiltrace.Field{"key", key},
utiltrace.Field{"resourceVersion", resourceVersion},
utiltrace.Field{"limit", pred.Limit},
utiltrace.Field{"continue", pred.Continue})
defer trace.LogIfLong(500 * time.Millisecond)
listPtr, err := meta.GetItemsPtr(listObj)
if err != nil {

View File

@ -96,7 +96,9 @@ func (b *backend) processEvents(ev ...*auditinternal.Event) error {
list.Items = append(list.Items, *e)
}
return b.w.WithExponentialBackoff(func() rest.Result {
trace := utiltrace.New(fmt.Sprintf("Audit events webhook request for %s, event list count: %d", b.name, len(list.Items)))
trace := utiltrace.New("Call Audit Events webhook",
utiltrace.Field{"name", b.name},
utiltrace.Field{"event-count", len(list.Items)})
// Only log audit webhook traces that exceed a 25ms per object limit plus a 50ms
// request overhead allowance. The high per object limit used here is primarily to
// allow enough time for the serialization/deserialization of audit events, which

View File

@ -166,7 +166,7 @@ func (r *Reflector) ListAndWatch(stopCh <-chan struct{}) error {
options := metav1.ListOptions{ResourceVersion: "0"}
if err := func() error {
initTrace := trace.New("Reflector " + r.name + " ListAndWatch")
initTrace := trace.New("Reflector ListAndWatch", trace.Field{"name", r.name})
defer initTrace.LogIfLong(10 * time.Second)
var list runtime.Object
var err error