Build iOS part tasks in slices so the next mutate() does not wait

CHANGELOG.md

@@ -116,6 +116,35 @@ pending until the returned function is called, so a test can model a native
 that is slow to answer. Later enqueues wait behind it, as they do on a
 device.
 
+iOS no longer makes a `mutate()` wait while a chunked upload copies all of
+its parts. Since 11.0.0, a chunked `mutate()` copied every part out of the
+file and created every part task in one block on the queue, so the next
+`mutate()` waited for all of it. For a 2 GiB file on an older iPhone this
+could pass the 10 s enqueue timeout. The parts are now built in slices of
+about 32 MiB, and other calls run between two slices: a `mutate()` waits for
+at most one slice per chunked upload that is building its parts. Each slice
+writes the task map once; before, every part task wrote the whole task map.
+The part copy frees each 1 MiB read buffer before the next read. The parts
+still get their tasks right after `mutate()`, one slice after the other. A
+background wake keeps its completion handler until the last slice is built,
+or until less than 5 s of background time is left. Replacing the part tasks
+created in the background, when the app becomes active, is sliced the same
+way, and each part keeps its old task until its new one exists, unless
+that slice's build fails. Each slice checks again that an old task has not
+started sending; one that has is kept. Replacing stops when the app leaves
+the foreground again.
+
+iOS now resumes every task it adopts at launch. A crash between writing a
+task's task map entry and resuming it left a suspended task that held its
+part, or its request, and never sent.
+
+On iOS, a running chunked upload past its `expiresAt` now settles `expired`
+when the app becomes active and its background-created part tasks are due
+for replacement. Before, it got new part tasks.
+
+iOS adds `os_signpost` intervals for each enqueue, issue and part slice, so
+Instruments can show how long each one holds the queue.
+
 ## 11.1.0
 
 Added `takeDiagnostics()`. On Android it returns the module's recent
@@ -151,8 +180,8 @@ A replaced simple request whose body landed anyway now completes its entry,
 even when its replacement failed and the entry moved to a later attempt.
 Before, the late success was dropped and the request was sent again.
 
-A chunked upload saves its entry and the task map once per batch of part
-tasks instead of once per part.
+A chunked upload saves its entry once per batch of part tasks instead of
+once per part.
 
 ## 11.0.0
 

README.md

@@ -55,6 +55,17 @@ relaunched with no JS running, so queued completions get journaled. `RNFileUploa
 is the TurboModule and is deliberately not reachable from plain Objective-C, because its
 generated header is Objective-C++ only. So the handler lives on `RNBackgroundUpload`.
 
+The library calls the handler when its work for the wake is done: after the
+relaunch reconcile, its grace waits, and every queued slice of chunked part
+tasks (see "Every part is queued at once"). A part slice can take long on an
+older device, so the library stops waiting for slices when less than 5 s of
+background time is left, and calls the handler then. The parts not built yet
+get their tasks at the next wake or launch. Usually that wake comes, because
+the upload already has the tasks of its first slice and the system wakes the
+app when one of them finishes. It may not come when no slice of the upload
+could be built (a full disk, for example): then only an in-process timer
+retries the build, and the parts wait until the app next runs.
+
 # Usage
 
 The library owns a durable queue of HTTP requests: JSON bodies, multipart
@@ -226,16 +237,25 @@ two background sessions (cellular allowed, and Wi-Fi only) sets
 `httpMaximumConnectionsPerHost = 4`. That caps connections to one host, not
 requests: over HTTP/2, every queued part can be in flight at once.
 
-**Every part is queued at once.** A chunked upload creates a task for every
-part at `mutate()`. Each part task reads its own part file, so a chunked
+**Every part is queued at once.** A chunked upload starts creating a task
+for every part at `mutate()`. It copies the parts and creates their tasks in
+slices of about 32 MiB, one slice at a time, and other calls run between two
+slices. So a `mutate()` right after a large chunked one waits for at most one
+slice per chunked upload that is building its parts, not for whole files. Each part task reads its own part file, so a chunked
 upload needs the file's size again in free space until its parts are sent.
 
+**Instruments.** Each `enqueue`, each `issue` and each part slice is an
+`os_signpost` interval (subsystem `ai.openspace.rnbgupload`, Points of
+Interest), with the entry id and the part count.
+
 **Not at the system's discretion.** Both sessions set
 `isDiscretionary = false`, but iOS only honors that for a task created while
 the app is in the foreground. It starts a task created in the background at
 its own discretion, for example when the device charges. Tasks are often
 created in the background: a retry scheduled while the app is there, a
-`mutate()` from a background wake, and the tasks a relaunch rebuilds. So the library records whether the app was active when it created
+`mutate()` from a background wake, the tasks a relaunch rebuilds, and the
+part tasks of a chunked upload whose slice runs after the app leaves the
+foreground. So the library records whether the app was active when it created
 each task. Two seconds after the app becomes active, it replaces every task
 created while the app was not active, unless the task has sent a byte of its
 body or has a response. The delay lets the system report what the task did

example/RNBGUExample/App.tsx

@@ -29,6 +29,7 @@ import {
   remove,
   type TestFile,
 } from './harness/files';
+import {LATENCY_RUNS, measureEnqueueLatency} from './harness/latency';
 import {clearLog, clock, getLog, log, subscribeLog} from './harness/log';
 import type {LogEntry, LogKind} from './harness/log';
 import {saveSettings, settings} from './harness/settings';
@@ -210,6 +211,9 @@ const App = () => {
         ...[1, 2, 3].map(() => enqueueJson('slow', undefined)),
       ]);
     }),
+    latency: run(`Enqueue latency x${LATENCY_RUNS}`, () =>
+      measureEnqueueLatency(settings.host),
+    ),
     stats: run('Server stats', async () =>
       (await fetch(`${settings.host}/stats`)).json(),
     ),
@@ -386,6 +390,13 @@ const App = () => {
               disabled={!isReady}
             />
           </Row>
+          <Row>
+            <Btn
+              title={`Enqueue latency x${LATENCY_RUNS}: 2 GiB, 20 MiB parts, on /slow`}
+              onPress={actions.latency}
+              disabled={!isReady}
+            />
+          </Row>
           <Row>
             <Btn
               title="Missing file"

example/RNBGUExample/README.md

@@ -99,7 +99,8 @@ writes the bytes at their offset into `example/server/received/`. It prints
   PUT" (the log says whether the source was moved), "DELETE" (bodiless),
   "GET (no vars)" (bodiless, `mutate()` with no arguments), "3 JSON at once",
   "Cap test" (resets the server counters, then 3 chunked and 3 JSON uploads on
-  `slow`), "Missing file", and "GET with a body".
+  `slow`), "Enqueue latency x7" (see iOS step 19), "Missing file", and "GET
+  with a body".
 - **Queue.** `pause()`, `resume()`, `cancel('nope')`, and a `setWifiOnly`
   switch. Native keeps the Wi-Fi setting and has no getter, so the switch
   shows the last value this app set. Below are the rows of `getRequests()`,
@@ -304,6 +305,25 @@ step says otherwise.
 
 18. **Dispatch latency.** Same as Android step 15. iOS creates a background
     session task per attempt, so this is the number to watch.
+19. **Enqueue latency.** This is what Diana does after a capture: the file
+    `mutate()`, then at once the metadata `mutate()`. Use an older device,
+    such as an iPhone 11: the slow case came from one. Each run needs about
+    4 GiB free (the 2 GiB source copy and its part files), plus 2 GiB for the
+    source that the app keeps. A paused entry builds no parts, so the run
+    calls `resume()` first. Press "Enqueue latency x7". The first press makes the 2 GiB
+    source, which takes minutes. Then each of the 7 runs copies the source,
+    calls `mutate()` on it with 103 parts of 20 MiB, and at once calls
+    `mutate()` on a small JSON request. Both go to `slow`, so no part
+    finishes during a run. Then the app cancels both. Each run logs
+    `copyMs`, `fileMs` and `nextMs`. `nextMs` is how long the second
+    `mutate()` waits. The last line gives the median and the maximum of
+    `nextMs`. Pass: median under 500 ms and maximum under 2 s. To compare,
+    run it on the same device twice: "before" is a build of commit 56c51c9
+    (this button on top of 11.1.0's native code), "after" is a build of the
+    commit that adds the part slices or later. To see where the time
+    goes, record the app in Instruments with the os_signpost or Points of
+    Interest instrument: each `enqueue`, `issue` and `part slice` is an
+    interval.
 
 ## Tests
 

example/RNBGUExample/__tests__/App.test.tsx

@@ -41,6 +41,8 @@ jest.mock('react-native-fs', () => ({
   exists: jest.fn(() => Promise.resolve(false)),
   readFile: jest.fn(() => Promise.resolve('{}')),
   writeFile: jest.fn(() => Promise.resolve()),
+  stat: jest.fn(() => Promise.resolve({size: 2048 * 1024 * 1024})),
+  copyFile: jest.fn(() => Promise.resolve()),
 }));
 jest.mock('@notifee/react-native', () => ({
   __esModule: true,
@@ -112,3 +114,43 @@ it('rejects a GET with a body before native sees it', async () => {
   await press(tree, 'GET with a body');
   expect(mockNative.enqueue.mock.calls.length).toBe(before);
 });
+
+it('runs the enqueue latency measurement 7 times on /slow', async () => {
+  const fs = require('react-native-fs') as {
+    exists: jest.Mock<(path: string) => Promise<boolean>>;
+    copyFile: jest.Mock;
+  };
+  // The 2 GiB source is already made.
+  fs.exists.mockImplementation(path =>
+    Promise.resolve(path.endsWith('/latency-src.bin')),
+  );
+  const before = mockNative.enqueue.mock.calls.length;
+  const resumes = mockNative.resume.mock.calls.length;
+  try {
+    await press(tree, 'Enqueue latency x7: 2 GiB, 20 MiB parts, on /slow');
+    for (let i = 0; i < 100 && mockNative.cancel.mock.calls.length < 14; i++) {
+      await act(async () => {
+        await new Promise(r => setTimeout(r, 0));
+      });
+    }
+  } finally {
+    fs.exists.mockImplementation(() => Promise.resolve(false));
+  }
+  const entries = mockNative.enqueue.mock.calls
+    .slice(before)
+    .map(c => c[0] as unknown as {key: string; descriptor: any});
+  expect(entries.map(e => e.key)).toEqual(
+    Array(7).fill(['harness.chunked20', 'harness.json']).flat(),
+  );
+  const parts = entries[0].descriptor.parts as Array<{
+    url: string;
+    headers: Record<string, string>;
+  }>;
+  expect(parts).toHaveLength(103);
+  expect(parts[0].url).toMatch(/\/slow\/chunk\/[\w-]+\/1$/);
+  expect(parts[0].headers['Content-Range']).toBe('0-20971519/2147483648');
+  expect(entries[1].descriptor.url).toMatch(/\/slow\/json\//);
+  expect(fs.copyFile).toHaveBeenCalledTimes(7);
+  expect(mockNative.cancel).toHaveBeenCalledTimes(14);
+  expect(mockNative.resume.mock.calls.length).toBe(resumes + 1);
+});

example/RNBGUExample/harness/files.ts

@@ -47,16 +47,24 @@ const ensureDir = async () => {
 
 export type TestFile = {path: string; size: number; md5: string};
 
-/** Writes a new file of `mb` MiB and returns its path, size, and MD5. */
-export const makeFile = async (name: string, mb: number): Promise<TestFile> => {
+/**
+ * Writes a new file of `mb` MiB and returns its path, size, and MD5. With
+ * `md5: false` the MD5 is '' (hashing a large file takes long).
+ */
+export const makeFile = async (
+  name: string,
+  mb: number,
+  options: {md5?: boolean} = {},
+): Promise<TestFile> => {
   await ensureDir();
   const path = `${TEST_DIR}/${name}`;
   await RNFS.writeFile(path, block(0), 'utf8');
   for (let i = 1; i < mb; i++) {
     await RNFS.appendFile(path, block(i), 'utf8');
   }
   const {size} = await RNFS.stat(path);
-  return {path, size: Number(size), md5: await RNFS.hash(path, 'md5')};
+  const md5 = options.md5 === false ? '' : await RNFS.hash(path, 'md5');
+  return {path, size: Number(size), md5};
 };
 
 /** Writes a new 1x1 JPEG and returns its path. */

example/RNBGUExample/harness/latency.ts

@@ -0,0 +1,113 @@
+import * as RNFS from 'react-native-fs';
+import Upload from 'react-native-background-upload';
+
+import {MB, TEST_DIR, makeFile, remove} from './files';
+import {log} from './log';
+import {postJson, putChunked20} from './uploads';
+
+// The enqueue latency run. It measures what Diana does after a capture: the
+// file mutate(), then at once the metadata mutate(). nextMs is how long the
+// second mutate() waits. Before 11.2.0 it waited while iOS copied every part
+// of the file, and a 2 GiB file could pass the 10 s enqueue timeout.
+
+export const LATENCY_RUNS = 7;
+const SOURCE_MB = 2048;
+const SOURCE_NAME = 'latency-src.bin';
+const SOURCE = `${TEST_DIR}/${SOURCE_NAME}`;
+
+/** The 2 GiB source, made one time and kept. Making it takes minutes. */
+const source = async (): Promise<number> => {
+  const size = SOURCE_MB * MB;
+  if (await RNFS.exists(SOURCE)) {
+    const stat = await RNFS.stat(SOURCE);
+    if (Number(stat.size) === size) {
+      return size;
+    }
+  }
+  log('action', `latency: making the ${SOURCE_MB} MiB source, one time`);
+  await makeFile(SOURCE_NAME, SOURCE_MB, {md5: false});
+  return size;
+};
+
+const sleep = (ms: number) => new Promise(r => setTimeout(r, ms));
+
+/**
+ * Waits until native forgets `ids` (cancel, then the automatic ack). Logs a
+ * warning when they are still there after 60 s.
+ */
+const waitGone = async (ids: string[]) => {
+  const until = Date.now() + 60_000;
+  const left = () => Upload.getRequests().filter(r => ids.includes(r.id));
+  while (left().length > 0) {
+    if (Date.now() >= until) {
+      log(
+        'warn',
+        `latency: still in the queue after 60 s: ${left()
+          .map(r => `${r.id} ${r.state}`)
+          .join(', ')}`,
+      );
+      return;
+    }
+    await sleep(200);
+  }
+};
+
+export type LatencyResult = {nextMs: number[]; median: number; max: number};
+
+/**
+ * LATENCY_RUNS runs. Each: copy the source, mutate() it as a chunked upload
+ * in 20 MiB parts, then at once mutate() a small JSON request. Both go to
+ * the server's `slow` mode, so no part finishes during the run. The run
+ * calls resume() first: a paused entry builds no parts. Then both are
+ * cancelled, so the next run has the disk space.
+ */
+export const measureEnqueueLatency = async (
+  host: string,
+): Promise<LatencyResult> => {
+  const size = await source();
+  // A paused entry builds no parts.
+  await Upload.resume();
+  const nextMs: number[] = [];
+  for (let i = 1; i <= LATENCY_RUNS; i++) {
+    const run = `${Date.now().toString(36)}-${i}`;
+    const file = `${TEST_DIR}/latency-${run}.bin`;
+    const c0 = Date.now();
+    await RNFS.copyFile(SOURCE, file);
+    const copyMs = Date.now() - c0;
+    const t0 = Date.now();
+    const cap = await putChunked20.mutate({
+      host,
+      path: `/slow/chunk/${run}`,
+      file,
+      size,
+    });
+    const t1 = Date.now();
+    const meta = await postJson.mutate({
+      host,
+      path: `/slow/json/${run}`,
+      n: i,
+      text: 'latency',
+    });
+    const t2 = Date.now();
+    nextMs.push(t2 - t1);
+    log(
+      'action',
+      `latency run ${i}/${LATENCY_RUNS}: copyMs=${copyMs} fileMs=${
+        t1 - t0
+      } nextMs=${t2 - t1}`,
+    );
+    await Upload.cancel(cap.id);
+    await Upload.cancel(meta.id);
+    await remove(file); // the library moved it; this is a guard
+    await waitGone([cap.id, meta.id]);
+  }
+  const sorted = [...nextMs].sort((a, b) => a - b);
+  const median = sorted[Math.floor(sorted.length / 2)];
+  const max = sorted[sorted.length - 1];
+  log(
+    'action',
+    `latency nextMs median=${median} max=${max} ` +
+      `(target: median < 500, max < 2000) all=${nextMs.join(',')}`,
+  );
+  return {nextMs, median, max};
+};