test: add log for locating docker push slow performance

Signed-off-by: Liang Zheng <zhengliang0901@gmail.com>

cmd/registry/config-dev.yml

@@ -10,7 +10,7 @@ storage:
     cache:
         blobdescriptor: inmemory
     filesystem:
-        rootdirectory: /var/lib/registry
+        rootdirectory: /mnt/ceph/registry
     maintenance:
         uploadpurging:
             enabled: false

cmd/registry/config-example.yml

@@ -6,7 +6,7 @@ storage:
   cache:
     blobdescriptor: inmemory
   filesystem:
-    rootdirectory: /var/lib/registry
+    rootdirectory: /mnt/ceph/registry
 http:
   addr: :5000
   headers:

registry/handlers/blobupload.go

@@ -28,7 +28,7 @@ func blobUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 		http.MethodHead: http.HandlerFunc(buh.GetUploadStatus),
 	}
 
-	if !ctx.readOnly {
+	if !ctx.readOnly { //not readonly
 		handler[http.MethodPost] = http.HandlerFunc(buh.StartBlobUpload)
 		handler[http.MethodPatch] = http.HandlerFunc(buh.PatchBlobData)
 		handler[http.MethodPut] = http.HandlerFunc(buh.PutBlobUploadComplete)

registry/handlers/helpers.go

@@ -8,6 +8,7 @@ import (
 	"net/http"
 	"strconv"
 	"strings"
+	"time"
 
 	"github.com/distribution/distribution/v3/internal/dcontext"
 )
@@ -37,7 +38,11 @@ func copyFullPayload(ctx context.Context, responseWriter http.ResponseWriter, r
 	}
 
 	// Read in the data, if any.
-	copied, err := io.Copy(destWriter, body)
+	start := time.Now()
+	copied, err := io.CopyBuffer(destWriter, body, make([]byte, 4<<20))
+	_, ok1 := destWriter.(io.WriterTo)
+	_, ok2 := body.(io.ReaderFrom)
+	dcontext.GetLogger(ctx).Infof("****The duration of io.Copy(size: %d) from reader(%T, %t) to writer(%T, %t): %v", copied, body, ok2, destWriter, ok1, time.Since(start))
 	if clientClosed != nil && (err != nil || (r.ContentLength > 0 && copied < r.ContentLength)) {
 		// Didn't receive as much content as expected. Did the client
 		// disconnect during the request? If so, avoid returning a 400

registry/storage/blobstore.go

@@ -75,6 +75,7 @@ func (bs *blobStore) Put(ctx context.Context, mediaType string, p []byte) (distr
 	if err != nil {
 		return distribution.Descriptor{}, err
 	}
+	dcontext.GetLogger(ctx).Infof("blobStore: the path is %s for dgst(%v), and the len(p) = %d", bp, dgst, len(p))
 
 	// TODO(stevvooe): Write out mediatype here, as well.
 	return distribution.Descriptor{

registry/storage/driver/base/base.go

@@ -90,7 +90,7 @@ func (base *Base) setDriverName(e error) error {
 // GetContent wraps GetContent of underlying storage driver.
 func (base *Base) GetContent(ctx context.Context, path string) ([]byte, error) {
 	ctx, done := dcontext.WithTrace(ctx)
-	defer done("%s.GetContent(%q)", base.Name(), path)
+	defer done("---->%s.XXGetContent(%q)", base.Name(), path)
 
 	if !storagedriver.PathRegexp.MatchString(path) {
 		return nil, storagedriver.InvalidPathError{Path: path, DriverName: base.StorageDriver.Name()}
@@ -105,7 +105,8 @@ func (base *Base) GetContent(ctx context.Context, path string) ([]byte, error) {
 // PutContent wraps PutContent of underlying storage driver.
 func (base *Base) PutContent(ctx context.Context, path string, content []byte) error {
 	ctx, done := dcontext.WithTrace(ctx)
-	defer done("%s.PutContent(%q)", base.Name(), path)
+	// defer done("%s.PutContent(%q)", base.Name(), path)
+	defer done("----->%s.XXPutContent(%q, len(content)=%d)", base.Name(), path, len(content))
 
 	if !storagedriver.PathRegexp.MatchString(path) {
 		return storagedriver.InvalidPathError{Path: path, DriverName: base.StorageDriver.Name()}
@@ -120,7 +121,7 @@ func (base *Base) PutContent(ctx context.Context, path string, content []byte) e
 // Reader wraps Reader of underlying storage driver.
 func (base *Base) Reader(ctx context.Context, path string, offset int64) (io.ReadCloser, error) {
 	ctx, done := dcontext.WithTrace(ctx)
-	defer done("%s.Reader(%q, %d)", base.Name(), path, offset)
+	defer done("--->%s.XXReader(%q, %d)", base.Name(), path, offset)
 
 	if offset < 0 {
 		return nil, storagedriver.InvalidOffsetError{Path: path, Offset: offset, DriverName: base.StorageDriver.Name()}
@@ -137,7 +138,7 @@ func (base *Base) Reader(ctx context.Context, path string, offset int64) (io.Rea
 // Writer wraps Writer of underlying storage driver.
 func (base *Base) Writer(ctx context.Context, path string, append bool) (storagedriver.FileWriter, error) {
 	ctx, done := dcontext.WithTrace(ctx)
-	defer done("%s.Writer(%q, %v)", base.Name(), path, append)
+	defer done("--->%s.XXWriter(%q, %v)", base.Name(), path, append)
 
 	if !storagedriver.PathRegexp.MatchString(path) {
 		return nil, storagedriver.InvalidPathError{Path: path, DriverName: base.StorageDriver.Name()}
@@ -150,7 +151,7 @@ func (base *Base) Writer(ctx context.Context, path string, append bool) (storage
 // Stat wraps Stat of underlying storage driver.
 func (base *Base) Stat(ctx context.Context, path string) (storagedriver.FileInfo, error) {
 	ctx, done := dcontext.WithTrace(ctx)
-	defer done("%s.Stat(%q)", base.Name(), path)
+	defer done("====>%s.Stat(%q)", base.Name(), path)
 
 	if !storagedriver.PathRegexp.MatchString(path) && path != "/" {
 		return nil, storagedriver.InvalidPathError{Path: path, DriverName: base.StorageDriver.Name()}
@@ -165,7 +166,7 @@ func (base *Base) Stat(ctx context.Context, path string) (storagedriver.FileInfo
 // List wraps List of underlying storage driver.
 func (base *Base) List(ctx context.Context, path string) ([]string, error) {
 	ctx, done := dcontext.WithTrace(ctx)
-	defer done("%s.List(%q)", base.Name(), path)
+	defer done("--->%s.List(%q)", base.Name(), path)
 
 	if !storagedriver.PathRegexp.MatchString(path) && path != "/" {
 		return nil, storagedriver.InvalidPathError{Path: path, DriverName: base.StorageDriver.Name()}
@@ -180,7 +181,7 @@ func (base *Base) List(ctx context.Context, path string) ([]string, error) {
 // Move wraps Move of underlying storage driver.
 func (base *Base) Move(ctx context.Context, sourcePath string, destPath string) error {
 	ctx, done := dcontext.WithTrace(ctx)
-	defer done("%s.Move(%q, %q", base.Name(), sourcePath, destPath)
+	defer done("--->%s.Move(%q, %q", base.Name(), sourcePath, destPath)
 
 	if !storagedriver.PathRegexp.MatchString(sourcePath) {
 		return storagedriver.InvalidPathError{Path: sourcePath, DriverName: base.StorageDriver.Name()}
@@ -197,7 +198,7 @@ func (base *Base) Move(ctx context.Context, sourcePath string, destPath string)
 // Delete wraps Delete of underlying storage driver.
 func (base *Base) Delete(ctx context.Context, path string) error {
 	ctx, done := dcontext.WithTrace(ctx)
-	defer done("%s.Delete(%q)", base.Name(), path)
+	defer done("---->%s.Delete(%q)", base.Name(), path)
 
 	if !storagedriver.PathRegexp.MatchString(path) {
 		return storagedriver.InvalidPathError{Path: path, DriverName: base.StorageDriver.Name()}

registry/storage/driver/filesystem/driver.go

@@ -12,6 +12,7 @@ import (
 	"path"
 	"time"
 
+	"github.com/distribution/distribution/v3/internal/dcontext"
 	storagedriver "github.com/distribution/distribution/v3/registry/storage/driver"
 	"github.com/distribution/distribution/v3/registry/storage/driver/base"
 	"github.com/distribution/distribution/v3/registry/storage/driver/factory"
@@ -28,6 +29,10 @@ const (
 	minThreads = uint64(25)
 )
 
+var (
+	copyBuf = 4 << 20
+)
+
 // DriverParameters represents all configuration options available for the
 // filesystem driver
 type DriverParameters struct {
@@ -124,10 +129,12 @@ func (d *driver) GetContent(ctx context.Context, path string) ([]byte, error) {
 	}
 	defer rc.Close()
 
+	start := time.Now()
 	p, err := io.ReadAll(rc)
 	if err != nil {
 		return nil, err
 	}
+	dcontext.GetLogger(ctx).Infof("***filesystem driver(GetContent): the path is %s, and the len(content) = %d, duration=%v", path, len(p), time.Since(start))
 
 	return p, nil
 }
@@ -139,13 +146,16 @@ func (d *driver) PutContent(ctx context.Context, subPath string, contents []byte
 		return err
 	}
 	defer writer.Close()
+	start := time.Now()
 	_, err = io.Copy(writer, bytes.NewReader(contents))
+	// _, err = io.CopyBuffer(writer, bytes.NewReader(contents), make([]byte, copyBuf))
 	if err != nil {
 		if cErr := writer.Cancel(ctx); cErr != nil {
 			return errors.Join(err, cErr)
 		}
 		return err
 	}
+	dcontext.GetLogger(ctx).Infof("***filesystem driver(PutContent): the path is %s, and the len(content) = %d, duration=%v", subPath, len(contents), time.Since(start))
 	return writer.Commit(ctx)
 }
 
@@ -361,7 +371,10 @@ func (fw *fileWriter) Write(p []byte) (int, error) {
 	} else if fw.cancelled {
 		return 0, fmt.Errorf("already cancelled")
 	}
+	start := time.Now()
 	n, err := fw.bw.Write(p)
+	dcontext.GetLogger(context.TODO()).Infof("***filesystem writer(Write): the len(content) = %d, size(filewriter) = %d, duration=%v",
+		len(p), fw.size, time.Since(start))
 	fw.size += int64(n)
 	return n, err
 }
@@ -375,13 +388,17 @@ func (fw *fileWriter) Close() error {
 		return fmt.Errorf("already closed")
 	}
 
+	start := time.Now()
 	if err := fw.bw.Flush(); err != nil {
 		return err
 	}
+	dcontext.GetLogger(context.TODO()).Infof("***filesystem writer(Flush): the duration=%v", time.Since(start))
 
+	start = time.Now()
 	if err := fw.file.Sync(); err != nil {
 		return err
 	}
+	dcontext.GetLogger(context.TODO()).Infof("***filesystem writer(Sync): the duration=%v", time.Since(start))
 
 	if err := fw.file.Close(); err != nil {
 		return err

registry/storage/linkedblobstore.go

@@ -125,7 +125,7 @@ func WithMountFrom(ref reference.Canonical) distribution.BlobCreateOption {
 
 // Create begins a blob write session, returning a handle.
 func (lbs *linkedBlobStore) Create(ctx context.Context, options ...distribution.BlobCreateOption) (distribution.BlobWriter, error) {
-	dcontext.GetLogger(ctx).Debug("(*linkedBlobStore).Create")
+	dcontext.GetLogger(ctx).Debug("(*linkedBlobStore).Create.XXBlobStoreWriter")
 
 	var opts distribution.CreateOptions