diff --git a/docs/26-atuq-envoltorio-gecko.md b/docs/26-atuq-envoltorio-gecko.md index 9c2b062d..76948fa2 100644 --- a/docs/26-atuq-envoltorio-gecko.md +++ b/docs/26-atuq-envoltorio-gecko.md @@ -1612,9 +1612,10 @@ es el de la jaula. La cadena entera funcionó —y esa parte también es medici 3. `atuq` **arranca**: sus extensiones inician y la del §6.5 sondea el foco cada minuto (`FOCO ESTADO unknown`), WebRender inicializa («Software WebRender», GL 3.2); 4. **y la ventana nunca aparece.** Cinco minutos, dos capturas, y el escritorio sigue vacío. - ⚠ **CORREGIDO el mismo día, ver §6.10.sexies: la ventana SÍ aparece, tarda.** Con el perfil - por defecto la primera pintura cae entre +137 s y +204 s del lanzamiento, y con la máquina - anfitriona cargada pasa de los +300 s. Lo que se midió acá fue la paciencia, no el producto. + ⚠ **MATIZADO el mismo día, ver §6.10.sexies: es INTERMITENTE.** Repetido cinco veces sobre esta + misma imagen, el navegador pintó en TRES (a +197…+204 s) y en dos no pintó —una de ellas con 15 + minutos de observación—. O sea que esto no era ni «nunca pinta» ni «sólo tardaba»: es un fallo que + aparece a veces, y una corrida sola no lo puede decidir en ningún sentido. **Lo que ya se descartó**, para que nadie lo repita: @@ -1716,44 +1717,60 @@ manda la siguiente encima. Y `cmd & ; echo …` es **error de sintaxis** en ash: lanzó y la corrida siguió como si todo fuera bien, con capturas de un escritorio vacío que se leían igual que el fallo que se estaba investigando. -#### 6.10.sexies El número: el navegador TARDA, no se queda sin pintar (2026-09-14) +#### 6.10.sexies El número: pinta a +197…+204 s — y **2 de 5 veces no pinta** (2026-09-14) -El §6.10.quinquies dejó una sola variable viva —cómo se lanza el navegador— y `--como-usuario` la -mide: `atuq` pelado, con SU perfil por defecto (el que está en la ext4 del disco y hace su primer -arranque entero: extensiones, Glean, barra lateral), tal como se tecleó en el serial aquella noche. +El §6.10.quinquies dejó una sola variable viva —cómo se lanza el navegador— y `--as-user` la mide: +`atuq` pelado, con SU perfil por defecto (el que vive en la ext4 y hace su primer arranque entero), +tal como se tecleó en el serial aquella noche. Cinco corridas sobre la MISMA imagen: -**Primera corrida, 300 s de observación: ninguna de las seis capturas muestra la ventana.** El -síntoma del §6.10.ter, reproducido. Pero el `MOZ_LOG` dice otra cosa a las 14:47:04, *después* de la -última captura: +| # | lanzamiento | vídeo | observación | primera pintura | +|---|---|---|---|---| +| 1 | perfil nuevo en tmpfs | `-vga none` | 180 s | **+197 s** | +| 2 | perfil nuevo en tmpfs | `VGA=1` | 240 s | **+197 s** | +| 3 | perfil del usuario | `VGA=1` | 291 s | ✗ no pintó | +| 4 | perfil del usuario | `VGA=1` | 900 s | **+204 s** | +| 5 | perfil del usuario | `VGA=1` | 900 s | ✗ **no pintó en 15 min** | - WaylandSurface::SetVSyncCallbackLocked(), enabled 1 mapped 1 - WaylandSurface::VSyncCallbackHandler() marked as visible & has buffer - WindowSurfaceWaylandMB::Lock [0,0] -> [1280 x 696] · WaylandBufferSHM::lock() · Commit - nsWindow::NotifyOcclusionState() mIsFullyOccluded 0 +⇒ **el fallo es INTERMITENTE**, y las corridas 4 y 5 son el mismo comando sobre la misma imagen. No +es el compositor (§6.10.quater), no es la segunda pantalla (§6.10.quinquies) y **tampoco es sólo que +tarde**: cuando pinta, pinta siempre alrededor de los 200 s; cuando no, no pinta aunque se le den +quince minutos. -o sea exactamente lo que hace cuando SÍ pinta. Así que la pregunta pasó a ser otra: ¿no pinta, o -tarda más que la paciencia que se le dio? +⚠ **La lección de método, y me la comí yo hoy mismo.** Entre la corrida 3 y la 4 publiqué que «la +ventana SÍ aparece, tarda», y el argumento era el `MOZ_LOG`: en la 3, treinta segundos después de la +última captura, Gecko decía `mapped 1`, «marked as visible & has buffer» y commiteaba un +`WaylandBufferSHM` de 1280×696 — lo mismo que hace cuando pinta. La corrida 5 lo refutó: **commiteaba +cuadros desde ≤ +377 s y la pantalla estaba vacía a los 900 s.** O sea que *el cliente cree que está +visible* no es evidencia de que se vea; la evidencia es el píxel. Un log en verde compatible con una +pantalla vacía es exactamente el cuadro contra el que este documento viene advirtiendo, y aun así lo +usé para cerrar una pregunta. Ver [[la-etiqueta-no-es-el-hecho]]. -**Segunda corrida, 900 s y captura cada 60 s. Tarda:** +**Dónde queda el número, para que no viva en el scrollback de quien corrió la VM** —que es como se +perdió el de la primera corrida—: `scripts/cosmic/atuq-en-imagen.py` mide la primera pintura y +**acumula** cada corrida en `docs/state/primera-pintura.json` con sus condiciones (lanzamiento, +vídeo, RAM, vcpus, cadencia = resolución del número). Acumula y no pisa **porque el fenómeno es +intermitente**: un fichero de una sola medición convierte esto en «+204 s» o en «no pinta» según qué +corrida tocó última, que es la forma más cara de mentir con datos ciertos. Y `scripts/vigia-imagen.py` +—que mide artefactos en segundos y no arranca nada— lo LEE y lo informa como sexto dato: - +66s +137s fondo liso, sin ventana - +204s ██ 699 458 px magenta — la página, pintada - +268s … +526s 703 766 px, estable + == primera pintura en la imagen arrancada (no lo mide este vigía) + ⚠ pintaron 3 de 5 corridas · primera pintura +197…+204s + ✓ +197s perfil nuevo en tmpfs virtio-gpu solo (-vga none) + ✗ — perfil del usuario vga+virtio-gpu (dos DRM) + ✓ +204s perfil del usuario vga+virtio-gpu (dos DRM) + ✗ — perfil del usuario vga+virtio-gpu (dos DRM) + ⚠ en las que NO pintó, el MOZ_LOG igual decía `mapped 1` + «has buffer» + … -⇒ **la primera pintura cae entre +137 s y +204 s**, contra ~+134 s con perfil nuevo en tmpfs. Y en la -corrida anterior no había llegado a los +291 s: el mismo arranque, la misma imagen, y el tiempo -cambia con la carga de la máquina anfitriona (acá se comparte con una tanda de la granja). Bajo TCG y -sin KVM, «cinco minutos y dos capturas» no alcanza para distinguir *no pinta* de *todavía no pintó*. +⚠ **Y una trampa para cualquier medición sobre la imagen: `cosmic-idle` ATENÚA la pantalla.** Entre ++526 s y +590 s sin una sola entrada, los 703 766 px de `(255,0,255)` pasan a 703 779 px de +`(117,0,117)` — la misma ventana al 46 % de brillo. Por eso el detector cuenta magenta **con +tolerancia** y no por color exacto: contar el color exacto lee el escritorio dormido como «desapareció +la ventana». -**Lo que esto deja dicho, y no es poco:** las tres afirmaciones del §6.10.ter que quedan en pie son -que la cadena entera funciona y que el navegador arranca; la cuarta —«la ventana nunca aparece»— era -una medición de paciencia. Nada del compositor, del arranque real ni del vídeo estaba roto. - -⚠ **Y una trampa nueva para cualquier guardián que mire la imagen: `cosmic-idle` ATENÚA la pantalla.** -Entre +526 s y +590 s sin una sola entrada, los 703 766 px de `(255,0,255)` pasan a 703 779 px de -`(117,0,117)` — la misma ventana al 46 % de brillo. Una comparación por color exacto, o un diff de -píxeles contra una captura previa, da «cambió todo» o «no está la página» cuando lo único que pasó es -que el escritorio se durmió. Medir dentro de los primeros ~8 min, o mover el ratón. +**Lo que queda abierto**, y ahora con arnés para atacarlo: por qué a veces la superficie mapeada y con +buffer no llega a la pantalla. Lo próximo es mirarlo del lado del compositor —si el `xdg_toplevel` +recibe su `configure`, en qué workspace y en qué salida quedó la ventana— y correr N veces para tener +una tasa, no una anécdota. ### 6.11 Y ahora la pregunta que faltaba: ¿REPRODUCE? (2026-09-07) diff --git a/docs/state/primera-pintura.json b/docs/state/primera-pintura.json new file mode 100644 index 00000000..7dfcd959 --- /dev/null +++ b/docs/state/primera-pintura.json @@ -0,0 +1,84 @@ +{ + "corridas": [ + { + "medido": "2026-09-14T14:28:00Z", + "imagen": "/mnt/cosecha/takana-cosmic-qemu.img", + "segundos_primera_pintura": 197, + "presupuesto_s": 420, + "ventana_s": 180, + "cadencia_s": 63, + "lanzamiento": "perfil nuevo en tmpfs", + "video": "virtio-gpu solo (-vga none)", + "mem_mb": 2560, + "vcpus": 2, + "acel": "tcg", + "guion": "scripts/cosmic/atuq-en-imagen.py", + "capturas": "work/atuq-imagen-1tarjeta", + "nota": "reconstruida de las capturas guardadas" + }, + { + "medido": "2026-09-14T14:36:00Z", + "imagen": "/mnt/cosecha/takana-cosmic-qemu.img", + "segundos_primera_pintura": 197, + "presupuesto_s": 420, + "ventana_s": 240, + "cadencia_s": 66, + "lanzamiento": "perfil nuevo en tmpfs", + "video": "vga+virtio-gpu (dos DRM)", + "mem_mb": 2560, + "vcpus": 2, + "acel": "tcg", + "guion": "scripts/cosmic/atuq-en-imagen.py", + "capturas": "work/atuq-imagen-2tarjetas", + "nota": "reconstruida de las capturas guardadas" + }, + { + "medido": "2026-09-14T14:47:00Z", + "imagen": "/mnt/cosecha/takana-cosmic-qemu.img", + "segundos_primera_pintura": null, + "presupuesto_s": 420, + "ventana_s": 291, + "cadencia_s": 71, + "lanzamiento": "perfil del usuario", + "video": "vga+virtio-gpu (dos DRM)", + "mem_mb": 2560, + "vcpus": 2, + "acel": "tcg", + "guion": "scripts/cosmic/atuq-en-imagen.py", + "capturas": "work/atuq-imagen-comousuario", + "nota": "reconstruida; el MOZ_LOG commiteaba buffers a +330 s, DESPUÉS de la última captura" + }, + { + "medido": "2026-09-14T15:10:00Z", + "imagen": "/mnt/cosecha/takana-cosmic-qemu.img", + "segundos_primera_pintura": 204, + "presupuesto_s": 420, + "ventana_s": 900, + "cadencia_s": 66, + "lanzamiento": "perfil del usuario", + "video": "vga+virtio-gpu (dos DRM)", + "mem_mb": 2560, + "vcpus": 2, + "acel": "tcg", + "guion": "scripts/cosmic/atuq-en-imagen.py", + "capturas": "work/atuq-imagen-usuario-largo", + "nota": "reconstruida de las capturas guardadas" + }, + { + "medido": "2026-09-14T15:58:44Z", + "imagen": "/mnt/cosecha/takana-cosmic-qemu.img", + "segundos_primera_pintura": null, + "presupuesto_s": 420, + "ventana_s": 900, + "cadencia_s": 30, + "lanzamiento": "perfil del usuario", + "video": "vga+virtio-gpu (dos DRM)", + "mem_mb": 2560, + "vcpus": 2, + "acel": "tcg", + "guion": "scripts/cosmic/atuq-en-imagen.py", + "capturas": "work/atuq-imagen-medicion", + "nota": "NO pintó en 900 s y el MOZ_LOG commiteaba WaylandBufferSHM desde ≤ +377 s: «mapped 1» NO prueba que se vea" + } + ] +} diff --git a/scripts/cosmic/atuq-en-imagen.py b/scripts/cosmic/atuq-en-imagen.py index b4932f31..b47ead4f 100755 --- a/scripts/cosmic/atuq-en-imagen.py +++ b/scripts/cosmic/atuq-en-imagen.py @@ -2,7 +2,7 @@ """atuq-en-imagen.py — arranca la IMAGEN DE DISCO con COSMIC y le pide al navegador que pinte. scripts/cosmic/atuq-en-imagen.py # lanza atuq y fotografía la pantalla - scripts/cosmic/atuq-en-imagen.py --solo-cosmic # control: NO lanza atuq (línea de base) + scripts/cosmic/atuq-en-imagen.py --only-cosmic # control: NO lanza atuq (línea de base) ── POR QUÉ ──────────────────────────────────────────────────────────────────────────────────── El §6.10.ter del SDD 26 dejó esto medido y sin explicar: en la imagen arrancada `atuq` corre —sus @@ -115,6 +115,67 @@ class Serial: return self.esperar(marca, segundos, nombre=f"de «{orden[:40]}»") +def pintado(ppm): + """¿Cuántos píxeles de la pantalla son la página de prueba? + + Se cuenta el magenta con TOLERANCIA, no por color exacto, y la razón está medida: a los ~+590 s + sin una sola entrada `cosmic-idle` ATENÚA la pantalla y los 703 766 px de `(255,0,255)` pasan a + 703 779 px de `(117,0,117)` —la misma ventana al 46 % de brillo—. Un contador por color exacto + lee eso como «desapareció la ventana», que es justo el error que este guion existe para no + cometer. + """ + try: + from PIL import Image + except Exception: + return None + im = Image.open(ppm).convert("RGB") + return sum(n for n, (r, g, b) in im.getcolors(1 << 24) if r > 90 and b > 90 and g < 40) + + +def anotar_medicion(segundos, a): + """Deja el tiempo de primera pintura en `docs/state/primera-pintura.json`. + + Va al estado del repo y no a un log porque quien pregunta «¿esta imagen se puede usar?» es + `scripts/vigia-imagen.py`, que mira artefactos y no arranca ninguna VM: el número tiene que + llegarle por escrito o no le llega. Se guarda TODO lo que lo hace comparable —cómo se lanzó, con + qué vídeo, con cuánta RAM y cuántos cores— porque el tiempo depende de eso y de la carga de la + máquina anfitriona; un número sin sus condiciones invita a leerlo como si fuera del producto. + """ + dato = { + "medido": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()), + "imagen": IMG, + "segundos_primera_pintura": segundos, # None = no pintó dentro de la ventana + "presupuesto_s": a.budget, + "ventana_s": a.wait, + "cadencia_s": a.cadence, # la RESOLUCIÓN del número: ±cadencia + "lanzamiento": "perfil del usuario" if a.as_user else "perfil nuevo en tmpfs", + "video": "vga+virtio-gpu (dos DRM)" if VGA_ARGS == [] else "virtio-gpu solo (-vga none)", + "mem_mb": int(MEM), "vcpus": int(SMP), "acel": "tcg", + "guion": "scripts/cosmic/atuq-en-imagen.py", + } + # ⚠ SE ACUMULAN, NO SE PISAN. Medido el 2026-09-14: dos corridas IDÉNTICAS (mismo comando, + # misma imagen) dieron «+204 s» y «no pintó en 900 s». Un fichero de UNA medición convierte un + # fenómeno intermitente en el número que le tocó a la última corrida, que es la forma más cara + # de mentir con datos ciertos. + destino = os.path.join(RAIZ, "docs/state/primera-pintura.json") + try: + historia = {"corridas": []} + if os.path.exists(destino): + with open(destino) as f: + historia = json.load(f) + historia.setdefault("corridas", []).append(dato) + historia["corridas"] = historia["corridas"][-30:] + os.makedirs(os.path.dirname(destino), exist_ok=True) + with open(destino, "w") as f: + json.dump(historia, f, indent=2, ensure_ascii=False) + f.write("\n") + pintaron = [c for c in historia["corridas"] if c.get("segundos_primera_pintura") is not None] + print(" anotada en docs/state/primera-pintura.json — %d de %d corridas pintaron" + % (len(pintaron), len(historia["corridas"]))) + except (OSError, ValueError) as e: + print(f" ⚠ no pude anotar la medición: {e}") + + def qmp(ruta, ordenes): s = socket.socket(socket.AF_UNIX); s.settimeout(30); s.connect(ruta) f = s.makefile("rwb", buffering=0) @@ -129,13 +190,19 @@ def qmp(ruta, ordenes): def main(): ap = argparse.ArgumentParser() - ap.add_argument("--solo-cosmic", action="store_true", help="control: no lanza el navegador") - ap.add_argument("--como-usuario", action="store_true", + ap.add_argument("--only-cosmic", action="store_true", help="control: no lanza el navegador") + ap.add_argument("--as-user", action="store_true", help="lanza `atuq` a secas —perfil por defecto, sin MOZ_ENABLE_WAYLAND— como se hizo a mano en el §6.10.ter") - ap.add_argument("--espera", type=int, default=180, help="segundos para que el navegador pinte") + ap.add_argument("--wait", type=int, default=600, help="segundos de observación como máximo") + ap.add_argument("--cadence", type=int, default=30, help="segundos entre capturas (la resolución de la medida)") + ap.add_argument("--budget", type=int, default=420, + help="segundos que puede tardar la primera pintura antes de dar ✗") + ap.add_argument("--until-paint", action="store_true", + help="cortar la observación en cuanto la página aparezca (más barato para medir el tiempo)") ap.add_argument("--out", default=os.path.join(RAIZ, "work/atuq-imagen")) a = ap.parse_args() + rc = [0] # lista para poder tocarlo desde dentro del try/finally out = a.out; os.makedirs(out, exist_ok=True) vars_fd = os.path.join(out, "OVMF_VARS.fd") shutil.copy(OVMF_VARS, vars_fd) @@ -180,7 +247,7 @@ def main(): qmp(qmp_sock, [{"execute": "screendump", "arguments": {"filename": os.path.join(out, "antes.ppm")}}]) print("== captura ANTES", flush=True) - if a.solo_cosmic: + if a.only_cosmic: print("== CONTROL: no se lanza el navegador") else: # Una página de un color imposible de confundir con el escritorio. @@ -195,7 +262,7 @@ def main(): # mano en el §6.10.ter —`atuq` pelado, con SU perfil y sin variables— que es lo único que # sigue distinto entre aquella corrida y ésta. El `MOZ_LOG` va en los dos: no cambia el # comportamiento, sólo deja rastro. - if a.como_usuario: + if a.as_user: lanz = ("MOZ_LOG='Widget:5,WidgetWayland:5,WaylandBackend:5,timestamp' " "MOZ_LOG_FILE=/var/log/cosmic/moz " "/usr/bin/atuq file:///tmp/pagina.html > /var/log/cosmic/atuq.log 2>&1 &") @@ -206,18 +273,49 @@ def main(): "/usr/bin/atuq --no-remote --profile /tmp/perfil file:///tmp/pagina.html " "> /var/log/cosmic/atuq.log 2>&1 &") print(ser.cmd(lanz, fondo=True).strip()) - print(f"== navegador lanzado; observando {a.espera}s", flush=True) + print(f"== navegador lanzado; observando {a.wait}s", flush=True) t0 = time.time(); n = 0 - while time.time() - t0 < a.espera: - time.sleep(min(60, max(5, a.espera / 3))); n += 1 - qmp(qmp_sock, [{"execute": "screendump", - "arguments": {"filename": os.path.join(out, f"durante-{n}.ppm")}}]) - vivos = ser.cmd("for c in /proc/[0-9]*/comm; do cat $c 2>/dev/null; done | grep -c atuq") - print(f" +{int(time.time()-t0)}s procesos atuq: {vivos.splitlines()[1].strip() if len(vivos.splitlines())>1 else '?'}", flush=True) + primera = None # segundos hasta la PRIMERA captura con la página en pantalla + while time.time() - t0 < a.wait: + time.sleep(a.cadence); n += 1 + shot = os.path.join(out, f"durante-{n}.ppm") + qmp(qmp_sock, [{"execute": "screendump", "arguments": {"filename": shot}}]) + t = int(time.time() - t0) + px = pintado(shot) + if primera is None and px and px > 100_000: + primera = t + print(f" +{t}s ██ PRIMERA PINTURA — {px} px de la página", flush=True) + if a.until_paint: + break + else: + vivos = ser.cmd("for c in /proc/[0-9]*/comm; do cat $c 2>/dev/null; done | grep -c atuq") + v = vivos.splitlines()[1].strip() if len(vivos.splitlines()) > 1 else "?" + print(f" +{t}s px de la página: {px if px is not None else '?'} procesos atuq: {v}", flush=True) qmp(qmp_sock, [{"execute": "screendump", "arguments": {"filename": os.path.join(out, "despues.ppm")}}]) print("== captura DESPUES", flush=True) + # EL NÚMERO. No «pinta / no pinta»: CUÁNTO TARDA. Medido el 2026-09-14 sobre esta misma + # imagen, la primera pintura cae entre +137 s y +204 s con el perfil por defecto y ~+134 s + # con uno nuevo en tmpfs — y con la máquina anfitriona cargada pasa de los +300 s. Por eso + # el presupuesto es HOLGADO y se dice el número siempre: un guardián que sólo contestara + # «no pintó» a los 5 min habría firmado el error del §6.10.ter. + if primera is None: + print(f"✗ el navegador NO pintó en {a.wait}s — mirá {out}/despues.png y el MOZ_LOG:") + print(" `mapped 1` + «marked as visible & has buffer» + WaylandBufferSHM ⇒ estaba pintando" + " y la captura llegó antes; sin eso, es un fallo de verdad") + rc[0] = 1 + else: + print(f"✓ primera pintura: +{primera}s (presupuesto {a.budget}s)") + if primera > a.budget: + print(f"✗ tardó {primera - a.budget}s MÁS que el presupuesto") + rc[0] = 1 + + # El número se PUBLICA donde lo pueda leer el vigía de la imagen, que es estático y no + # arranca nada: sin esto el dato vive en el scrollback del que corrió la VM y se pierde, + # que es exactamente lo que pasó con la corrida a mano del §6.10.ter. + anotar_medicion(primera, a) + # La evidencia que no se puede leer de una captura: qué hizo el widget de Wayland. print("---- atuq.log (cola) ----") print(ser.cmd("tail -25 /var/log/cosmic/atuq.log", 60)) @@ -248,7 +346,8 @@ def main(): print("== capturas convertidas a PNG en", out) except Exception as e: print(" ⚠ sin conversión a PNG:", e) + return rc[0] if __name__ == "__main__": - main() + sys.exit(main()) diff --git a/scripts/vigia-imagen.py b/scripts/vigia-imagen.py index fee65af2..c8fc00e3 100644 --- a/scripts/vigia-imagen.py +++ b/scripts/vigia-imagen.py @@ -38,6 +38,16 @@ # qml todo `import ` de los `.qml` INSTALADOS tiene un módulo con `qmldir` en el # cierre. Así se caza la clase (2). # +# ══ Y UN SEXTO DATO QUE ESTE VIGÍA NO MIDE: CUÁNTO TARDA EN VERSE ══════════════════════════════ +# Los cinco de arriba se miden sobre artefactos, en segundos, y contestan «¿está lo que hace falta?». +# Ninguno contesta «¿y cuándo se ve?» — y esa pregunta ya cobró: el §6.10.ter del SDD 26 dio por +# hecho que `atuq` «no pinta nunca» en la imagen arrancada CON ESTE VIGÍA EN ✓, y la medición +# repetida mostró que pintaba a los +137…+204 s. Lo medido había sido la paciencia. +# Arrancar la imagen son ~15 min de QEMU sin KVM, así que no se hace acá: `scripts/cosmic/atuq-en- +# imagen.py` lo mide y deja el número en `docs/state/primera-pintura.json`, y este vigía lo LEE y lo +# dice con sus condiciones (lanzamiento, vídeo, RAM, vcpus) — el tiempo depende de la carga de la +# anfitriona, y un número sin condiciones se lee como si fuera del producto. Sin medición, lo dice. +# # ══ RUIDO LEGÍTIMO, para poder triar ═══════════════════════════════════════════════════════════ # Hay módulos QML que NO se instalan en disco porque el binario los REGISTRA en runtime # (`org.kde.plasma.shell` lo registra plasmashell; los `Qt*` los trae el propio Qt en otra ruta). @@ -49,7 +59,7 @@ # --fail → exit 1 si algún invariante falla; exit 2 si NO SE PUDO medir (nodos del cierre # sin artefacto sellado). Los dos son accionables y no son lo mismo. # --qml → además del resumen, listar los imports sin módulo -import os, sys, glob, subprocess, re +import os, sys, glob, subprocess, re, json sys.path.insert(0, os.path.join(os.path.dirname(os.path.abspath(__file__)))) import yupana @@ -234,6 +244,64 @@ def escanear(nodos): return temas, cursores, fuentes, terminales, faltan_qml, sin_artefacto, en_binario +def informe_primera_pintura(): + """El sexto dato: CUÁNTO TARDA la ventana en aparecer en la imagen ARRANCADA. + + Los cinco invariantes de arriba se miden sobre artefactos y contestan «¿está lo que hace falta?». + Ninguno contesta «¿y cuándo se ve?», y esa pregunta ya cobró: el §6.10.ter del SDD 26 concluyó + que `atuq` «no pinta nunca» en la imagen con este vigía en ✓ — y la medición repetida mostró que + pintaba a los +137…+204 s, o sea que lo que se había medido era la paciencia del que miraba. + + No se mide acá a propósito: arrancar la imagen son ~15 min de QEMU sin KVM y este guion corre en + segundos sobre el store. Lo que hace es LEER el número que dejó `scripts/cosmic/atuq-en-imagen.py` + y decirlo con sus condiciones —tiempo sin condiciones se lee como si fuera del producto, y + depende de la carga de la máquina anfitriona—. Si no hay medición, se dice; un hueco callado acá + es un ✓ que no se ganó. + """ + ruta = os.path.join(str(ROOT), "docs/state/primera-pintura.json") + print("\n== primera pintura en la imagen arrancada (no lo mide este vigía)") + if not os.path.exists(ruta): + print(" ⊘ sin medición — corré: scripts/cosmic/atuq-en-imagen.py --as-user --until-paint") + return False + try: + with open(ruta) as f: + corridas = json.load(f).get("corridas", []) + except (OSError, ValueError) as e: + print(" ⚠ %s ilegible: %s" % (ruta, e)) + return False + if not corridas: + print(" ⊘ el fichero no tiene corridas") + return False + + # Se informan TODAS las corridas y no la última, porque el fenómeno es INTERMITENTE: el + # 2026-09-14 dos corridas idénticas dieron «+204 s» y «no pintó en 900 s». Un solo número acá + # sería el de la corrida que tocó, y el lector lo leería como el del producto. + pintaron = [c["segundos_primera_pintura"] for c in corridas + if c.get("segundos_primera_pintura") is not None] + n, m = len(pintaron), len(corridas) + marca = "✓" if n == m else ("✗" if n == 0 else "⚠") + if pintaron: + print(" %s pintaron %d de %d corridas · primera pintura %s" + % (marca, n, m, + ("+%ds" % pintaron[0]) if n == 1 else "+%d…+%ds" % (min(pintaron), max(pintaron)))) + else: + print(" %s NINGUNA de %d corridas pintó" % (marca, m)) + for c in corridas[-6:]: + seg = c.get("segundos_primera_pintura") + print(" %s %-9s %-22s %-26s %s" + % ("✓" if seg is not None else "✗", + ("+%ds" % seg) if seg is not None else "—", + c.get("lanzamiento", "?"), c.get("video", "?"), + (c.get("medido") or "")[:16])) + fallidas = [c for c in corridas if c.get("segundos_primera_pintura") is None] + if fallidas: + print(" ⚠ en las que NO pintó, el MOZ_LOG igual decía `mapped 1` + «has buffer» +" + " WaylandBufferSHM commiteado:") + print(" que Gecko commitee cuadros NO prueba que la ventana se vea. La evidencia es" + " el píxel, no el log.") + return n == 0 + + def main(): args = [a for a in sys.argv[1:] if not a.startswith("--")] fallar = "--fail" in sys.argv @@ -302,9 +370,10 @@ def main(): for m, quienes in sorted(faltan_qml.items()): print(" FALTA %-34s ← lo importa: %s" % (m, ", ".join(sorted(quienes)[:4]))) + fallo_pintura = informe_primera_pintura() if parciales: print("\n⚠ perfiles medidos a medias (deuda en el store): %s" % ", ".join(sorted(parciales))) - if fallar and fallos: + if fallar and (fallos or fallo_pintura): return 1 # medí y FALTA if fallar and parciales: return 2 # NO pude medir — distinto de «está bien»