Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Do not request string descriptor if index is 0 #5

Merged
merged 1 commit into from
Nov 5, 2022

Conversation

CodyJung
Copy link

@CodyJung CodyJung commented Nov 5, 2022

This is similar to a fix I made in 8397298 -- but impacts an API that only OpenMTP uses so I missed originally.

Garmin devices have a 0 index for a couple string descriptors, which is valid but means it's not available - so requesting it is incorrect behavior.

Part of the fix for ganeshrvel/openmtp#153

This is similar to a fix I made in 8397298 -- but impacts an API
that only OpenMTP uses so I missed originally.

Garmin devices have a 0 index for a couple string descriptors, which
is valid but means it's not available - so requesting it is incorrect
behavior.
@ganeshrvel ganeshrvel changed the base branch from master to fix/garmin November 5, 2022 04:08
@ganeshrvel ganeshrvel merged commit b428192 into ganeshrvel:fix/garmin Nov 5, 2022
@ganeshrvel
Copy link
Owner

awesome @CodyJung !

@ganeshrvel
Copy link
Owner

Hey @CodyJung,

I've been trying to figure out a peculiar problem when sending objects to MTP devices: there are inconsistent delays of approximately 1-1.5 seconds between sending objects, regardless of their size. This issue is especially puzzling for small files, which are taking just as long to transfer as medium-sized files.

I've checked the MTP specs and multiple other MTP implementations and followed their methods, but none of this has resolved the issue. Since you have better resources to understand the issue listed below, I'm hoping you could guide me regarding the problem.

Test Implementation

I've implemented a test in Go to transfer files of various sizes. Here's the relevant code snippet:

File: mtp/device_test.go

func TestAndroid(t *testing.T) {
    dev, err := SelectDevice("")
    if err != nil {
        t.Fatal(err)
    }
    defer dev.Close()
    //setDebug(dev)

    info := DeviceInfo{}
    err = dev.GetDeviceInfo(&info)
    if err != nil {
        t.Fatal("GetDeviceInfo failed:", err)
    }

    if !strings.Contains(info.MTPExtension, "android.com:") {
        t.Log("no android extensions", info.MTPExtension)
        return
    }

    if err = dev.Configure(); err != nil {
        t.Fatal("Configure failed:", err)
    }

    sids := Uint32Array{}
    err = dev.GetStorageIDs(&sids)
    if err != nil {
        t.Fatalf("GetStorageIDs failed: %v", err)
    }

    if len(sids.Values) == 0 {
        t.Fatalf("No storages")
    }

    id := sids.Values[0]

    ////////////////////////////////
    // START: TEST multiple bulk writes
    ////////////////////////////////
    dataLengths := []int{1000000, 0, 1, 2, 10, 100, 10, 100, 500, 500, 65536, 65535, 65024, 64524, 65524, 1000000, 5000000, 5000500}
    // Pre-generate data
    var populatedData [][]byte
    for _, length := range dataLengths {
        data := make([]byte, length)
        for i := range data {
            data[i] = byte('0' + i%10)
        }
        populatedData = append(populatedData, data)
    }
    // Main test loop
    for i, testSize := range dataLengths {
        filename := fmt.Sprintf("test-mtp-file-%d-%d", time.Now().Unix(), rand.Intn(10000))
        send := ObjectInfo{
            StorageID:        id,
            ObjectFormat:     OFC_Undefined,
            ParentObject:     0xFFFFFFFF,
            Filename:         filename,
            CompressedSize:   uint32(testSize),
            ModificationDate: time.Now(),
            Keywords:         "bla",
        }
        _, _, _, err := dev.SendObjectInfo(id, 0xFFFFFFFF, &send)
        if err != nil {
            t.Fatal("SendObjectInfo failed:", err)
        } else {
            buf := bytes.NewBuffer(populatedData[i])
            startTime := time.Now()
            err = dev.SendObject(buf, int64(len(populatedData[i])), EmptyProgressFunc)
            duration := time.Since(startTime)
            if err != nil {
                t.Log("SendObject failed:", err)
            } else {
                transferSpeed := float64(testSize) / duration.Seconds() / 1024 / 1024 // MB/s
                t.Logf("Elapsed time to upload `%s`: File size: %s, %.2f seconds, %d milliseconds, Transfer speed: %.2f MB/s\n",
                    filename,
                    humanize.Bytes(uint64(testSize)), // "github.com/dustin/go-humanize"
                    duration.Seconds(),
                    duration.Milliseconds(),
                    transferSpeed)
            }
        }
    }
}

Test Results

Here are the logs from running this test:

1) Elapsed time to upload `test-mtp-file-1724338535-609`: File size: 1.0 MB, 0.07 seconds, 66 milliseconds, Transfer speed: 14.30 MB/s
2) Elapsed time to upload `test-mtp-file-1724338535-3453`: File size: 0 B, 0.02 seconds, 17 milliseconds, Transfer speed: 0.00 MB/s
3) Elapsed time to upload `test-mtp-file-1724338535-5216`: File size: 1 B, 0.01 seconds, 10 milliseconds, Transfer speed: 0.00 MB/s
4) Elapsed time to upload `test-mtp-file-1724338535-6958`: File size: 2 B, 0.01 seconds, 10 milliseconds, Transfer speed: 0.00 MB/s
5) Elapsed time to upload `test-mtp-file-1724338535-8761`: File size: 10 B, 0.01 seconds, 9 milliseconds, Transfer speed: 0.00 MB/s
6) Elapsed time to upload `test-mtp-file-1724338535-5819`: File size: 100 B, 0.01 seconds, 12 milliseconds, Transfer speed: 0.01 MB/s

# Up to this point, the objects were transferred quickly, but after this, each object takes around 1 second to transfer.

7) Elapsed time to upload `test-mtp-file-1724338535-4078`: File size: 10 B, 1.08 seconds, 1077 milliseconds, Transfer speed: 0.00 MB/s
8) Elapsed time to upload `test-mtp-file-1724338536-1490`: File size: 100 B, 1.06 seconds, 1059 milliseconds, Transfer speed: 0.00 MB/s
9) Elapsed time to upload `test-mtp-file-1724338537-7539`: File size: 500 B, 1.03 seconds, 1031 milliseconds, Transfer speed: 0.00 MB/s
10) Elapsed time to upload `test-mtp-file-1724338538-1694`: File size: 500 B, 1.03 seconds, 1026 milliseconds, Transfer speed: 0.00 MB/s
11) Elapsed time to upload `test-mtp-file-1724338539-9760`: File size: 66 kB, 1.04 seconds, 1038 milliseconds, Transfer speed: 0.06 MB/s
12) Elapsed time to upload `test-mtp-file-1724338540-8081`: File size: 66 kB, 1.03 seconds, 1034 milliseconds, Transfer speed: 0.06 MB/s
13) Elapsed time to upload `test-mtp-file-1724338541-7618`: File size: 65 kB, 1.05 seconds, 1053 milliseconds, Transfer speed: 0.06 MB/s
14) Elapsed time to upload `test-mtp-file-1724338542-2291`: File size: 64 kB, 1.04 seconds, 1037 milliseconds, Transfer speed: 0.06 MB/s
15) Elapsed time to upload `test-mtp-file-1724338543-2798`: File size: 66 kB, 1.03 seconds, 1026 milliseconds, Transfer speed: 0.06 MB/s
16) Elapsed time to upload `test-mtp-file-1724338544-1628`: File size: 1.0 MB, 1.12 seconds, 1118 milliseconds, Transfer speed: 0.85 MB/s
17) Elapsed time to upload `test-mtp-file-1724338545-8430`: File size: 5.0 MB, 1.20 seconds, 1199 milliseconds, Transfer speed: 3.98 MB/s
18) Elapsed time to upload `test-mtp-file-1724338547-2506`: File size: 5.0 MB, 1.20 seconds, 1196 milliseconds, Transfer speed: 3.99 MB/s
19) Elapsed time to upload `test-mtp-file-1724338251-2639`: File size: 5.0 MB, 1.19 seconds, 1192 milliseconds, Transfer speed: 4.00 MB/s

Key Observations

  1. This happens every time after sending the 5th or 6th object.
  2. Until the 6th file, objects were transferred very quickly.
  3. From the 7th file onwards, objects take ~1sec to transfer, regardless of size.
  4. Note, how the first file (1MB) completed quickly (66ms).
  5. After the 6th file, even larger files (1.0MB or 5.0MB) take about the same time as smaller files (64KB or 100 Bytes).

Analysis So Far

I believe short packet sending could be a potential reason for this behavior:

  1. Previously, the timeout for the short packet was 10000ms (10 sec).
    • Users complained of very slow file transfers.
    • Investigation showed that the short packet waited for the packet to timeout at 10 secs.
  2. Reducing the timeout for null packets made the send object faster, but the ~1sec delay persisted.

Relevant code:

d.h.BulkTransfer(d.sendEP, buf[:0], 250)

if lastTransfer%packetSize == 0 {
    // write a short packet just to be sure.
    d.h.BulkTransfer(d.sendEP, buf[:0], 250) // timeout = 250ms
}
  1. Further investigation suggests that the fetchPacket method is causing this ~1sec latency issue.
  2. After bulk_write of 5 or 6 objects, BulkTransfer in fetchPacket takes approximately 1sec to fetch the data, regardless of size.
  3. Interestingly, this ~1sec timeout is inclusive of the short packet timeout.
    • If I set the short packet timeout is set to 700ms, the subsequent fetchPacket only takes about 300-400ms to complete the request after sending 6 objects.
    • This is really weird; something is clearly delaying the upload of the objects by approximately 1 second.

Relevant code:

func (d *Device) fetchPacket(dest []byte, header *usbBulkHeader) (rest []byte, bytesRead int, err error) {

// Fetches one USB packet. The header is split off, and the remainder is returned.
// dest should be at least 512bytes.
func (d *Device) fetchPacket(dest []byte, header *usbBulkHeader) (rest []byte, bytesRead int, err error) {
    n, err := d.h.BulkTransfer(d.fetchEP, dest[:d.fetchMaxPacketSize()], d.Timeout)
    if n > 0 {
        d.dataPrint(d.fetchEP, dest[:n])
    }
    // ...
}

Could this be happening due to an internal buffer in the MTP device that, when filled with, say, 5 or 6 objects, takes time to clear, keeping the device busy until then?

This is a significant performance bottleneck when transacting many tiny files.

I would greatly appreciate any insights or guidance on resolving this issue.

Thank you for your time and effort!

@CodyJung
Copy link
Author

So the good news is that I don't see the same issue when transferring data to my watch:

    Elapsed time to upload `test-mtp-file-1724377449-3789`: File size: 1000000, 0.37 seconds, 372 milliseconds, Transfer speed: 2.56 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-8552`: File size: 1, 0.10 seconds, 97 milliseconds, Transfer speed: 0.00 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-4515`: File size: 2, 0.01 seconds, 5 milliseconds, Transfer speed: 0.00 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-8081`: File size: 10, 0.01 seconds, 6 milliseconds, Transfer speed: 0.00 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-8459`: File size: 100, 0.03 seconds, 29 milliseconds, Transfer speed: 0.00 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-5021`: File size: 10, 0.01 seconds, 6 milliseconds, Transfer speed: 0.00 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-5707`: File size: 100, 0.01 seconds, 8 milliseconds, Transfer speed: 0.01 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-9723`: File size: 500, 0.01 seconds, 6 milliseconds, Transfer speed: 0.08 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-6209`: File size: 500, 0.01 seconds, 7 milliseconds, Transfer speed: 0.06 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-124`: File size: 65536, 0.01 seconds, 14 milliseconds, Transfer speed: 4.39 MB/s
    Elapsed time to upload `test-mtp-file-1724377450-1443`: File size: 65535, 0.15 seconds, 146 milliseconds, Transfer speed: 0.43 MB/s
    Elapsed time to upload `test-mtp-file-1724377451-8543`: File size: 65024, 0.13 seconds, 128 milliseconds, Transfer speed: 0.48 MB/s
    Elapsed time to upload `test-mtp-file-1724377451-512`: File size: 64524, 0.13 seconds, 128 milliseconds, Transfer speed: 0.48 MB/s
    Elapsed time to upload `test-mtp-file-1724377451-6834`: File size: 65524, 0.06 seconds, 62 milliseconds, Transfer speed: 1.01 MB/s
    Elapsed time to upload `test-mtp-file-1724377451-112`: File size: 1000000, 0.49 seconds, 485 milliseconds, Transfer speed: 1.96 MB/s
    Elapsed time to upload `test-mtp-file-1724377452-4532`: File size: 5000000, 1.13 seconds, 1128 milliseconds, Transfer speed: 4.23 MB/s
    Elapsed time to upload `test-mtp-file-1724377454-6932`: File size: 5000500, 1.11 seconds, 1105 milliseconds, Transfer speed: 4.31 MB/s

I bumped up the number of small files to ~50, and never saw a file take more than 96 milliseconds.

Same story for my Fujifilm camera:

device_test.go:99: Elapsed time to upload `test-mtp-file-1724377449-3789`: File size: 1000000, 0.37 seconds, 372 milliseconds, Transfer speed: 2.56 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-8552`: File size: 1, 0.10 seconds, 97 milliseconds, Transfer speed: 0.00 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-4515`: File size: 2, 0.01 seconds, 5 milliseconds, Transfer speed: 0.00 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-8081`: File size: 10, 0.01 seconds, 6 milliseconds, Transfer speed: 0.00 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-8459`: File size: 100, 0.03 seconds, 29 milliseconds, Transfer speed: 0.00 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-5021`: File size: 10, 0.01 seconds, 6 milliseconds, Transfer speed: 0.00 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-5707`: File size: 100, 0.01 seconds, 8 milliseconds, Transfer speed: 0.01 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-9723`: File size: 500, 0.01 seconds, 6 milliseconds, Transfer speed: 0.08 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-6209`: File size: 500, 0.01 seconds, 7 milliseconds, Transfer speed: 0.06 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-124`: File size: 65536, 0.01 seconds, 14 milliseconds, Transfer speed: 4.39 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377450-1443`: File size: 65535, 0.15 seconds, 146 milliseconds, Transfer speed: 0.43 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377451-8543`: File size: 65024, 0.13 seconds, 128 milliseconds, Transfer speed: 0.48 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377451-512`: File size: 64524, 0.13 seconds, 128 milliseconds, Transfer speed: 0.48 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377451-6834`: File size: 65524, 0.06 seconds, 62 milliseconds, Transfer speed: 1.01 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377451-112`: File size: 1000000, 0.49 seconds, 485 milliseconds, Transfer speed: 1.96 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377452-4532`: File size: 5000000, 1.13 seconds, 1128 milliseconds, Transfer speed: 4.23 MB/s
device_test.go:99: Elapsed time to upload `test-mtp-file-1724377454-6932`: File size: 5000500, 1.11 seconds, 1105 milliseconds, Transfer speed: 4.31 MB/s

I'm wondering if there's something specific to the Android MTP implementation?

@CodyJung
Copy link
Author

I started looking through the AOSP source, and it seems like there might be an intentional pause (there's a 500ms x2 poll time, if I'm reading it right), but I also don't understand why it would start being an issue after a certain number of requests.

I don't have an Android phone handy tonight, and honestly I'm not sure how much debugging I'll be able to do.

@ganeshrvel
Copy link
Owner

ganeshrvel commented Aug 23, 2024

@CodyJung Thanks for your input. What’s even stranger is that the 1-second delay sometimes doesn’t occur at all, although this is rare.
This happened just yesterday while I was preparing the test samples.

However, after reconnecting the device, the delay issue started happening again. Not sure what nerve I touched that made the issue temporarily disappear.

I will go through the AOSP code and see what I can find.

Thanks a lot! 🔥🔥

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants