[Bug]: WorkflowProfiler reports zero elapsed time on Windows with Python <= 3.12

Abierto
  • ¿Algo no está bien?
#2,599 1 comentario 0 reacciones 0 asignados Ver en GitHub

Los mantenedores suelen responder en 5 días

Nadie ha tomado este issue todavía.

Evaluación

Dificultad
2/5
Tiempo estimado
1-3 horas
Aptitud para principiantes
38/100
Tipo de issue
Error
Claridad
Bien especificado
Estado de actividad
Activo
Stack tecnológico
python
Área
performance, testing-qa

Línea de trabajo

Start with WorkflowProfiler in profiling.py, total_runtime in run_pipeline.py, and tests/unit/indexing/test_profiling.py; check how elapsed time is measured and run the profiling tests on Windows with Python 3.11 or 3.12. Done means short workflows report positive elapsed time and pipeline runtime remains monotonic. The issue author says a fix and regression test are ready and that they plan to open a pull request, so check for work already underway before starting.

Escrito por el modelo de indexación a partir del texto del issue.

Descripción

Describe the bug

WorkflowProfiler (and the pipeline total_runtime in run_pipeline.py) measure elapsed time with time.time(). On Windows, time.time() has a 15.6 ms resolution with Python <= 3.12 (it uses GetSystemTimeAsFileTime); CPython 3.13 switched to GetSystemTimePreciseAsFileTime with a 1 microsecond resolution (What's New in Python 3.13 - time).

Since pyproject.toml declares requires-python = ">=3.11,<3.14" but the unit-test CI matrix only runs Python 3.13, this bug is invisible to CI and affects every Windows user on Python 3.11/3.12:

  1. context.stats.workflows[name] = profiler.metrics writes overall = 0.0 for any workflow body shorter than one scheduler tick, so stats.json reports 0 ms per workflow on Windows with Python 3.11/3.12.
  2. tests/unit/indexing/test_profiling.py::TestWorkflowProfiler::test_handles_exception_in_context fails deterministically (assert 0.0 > 0), because the test body is microsecond-scale.
  3. time.time() is also a wall clock, so NTP adjustments can make elapsed/total_runtime negative or inflated; time.perf_counter() is the documented clock for measuring elapsed durations.
Steps to reproduce

On Windows with Python 3.11 or 3.12:

uv sync --all-packages
uv run pytest tests/unit/indexing/test_profiling.py

test_handles_exception_in_context fails with assert 0.0 > 0 on both 3.11.15 and 3.12.4 (verified: 11/11 pytest runs across both versions). A 300-iteration measurement of the exact try/with/raise block used by the test reports 298/300 zero elapsed values (99.3%), median 0.0, max 1.0 ms. The same test passes on Python 3.13 (3/3), which is exactly why the CI matrix (Python 3.13 only x ubuntu/windows) stays green while the supported versions fail.

Minimal clock probe on Windows, Python 3.12.4:

import time
zero = sum(
    (lambda t0: ([0] * 1000, time.time() - t0)[1] == 0.0)(time.time())
    for _ in range(200)
)
# -> 200/200 zero samples for a microsecond-scale body
Expected Behavior

WorkflowProfiler.overall and pipeline.total_runtime must be positive and monotonic regardless of Python version or OS. Elapsed-time measurement should use time.perf_counter() (high-resolution monotonic clock), per the Python docs recommendation for benchmarking.

GraphRAG Config Used

Not config-dependent; reproducible with the unit test suite alone.

Logs and screenshots
FAILED tests/unit/indexing/test_profiling.py::TestWorkflowProfiler::test_handles_exception_in_context - assert 0.0 > 0
 +  where 0.0 = WorkflowMetrics(overall=0.0, peak_memory_bytes=8480, memory_delta_bytes=8480, tracemalloc_overhead_bytes=1104).overall
Additional Information
  • GraphRAG Version: main (5faaaf4f5, post-3.3.0)
  • Operating System: Windows 11 (24H2, x64)
  • Python Version: 3.11.15, 3.12.4 (failing), 3.13.x (passing)
  • Related Issues: none found for this failure mode

I have a minimal fix ready (time.perf_counter() in profiling.py + run_pipeline.py, plus a regression test guarding positive elapsed time for sub-tick bodies) and will open a PR referencing this issue.

Lenguaje dominante
Python
Estrellas
36.6k
Forks
3.9k
Merge medio
4 d 11 h
PR fusionados (30 d)
1

Preparar el entorno

Primeros pasos

  1. Lee el issue completo y luego la guía de contribución del proyecto.
  2. Comenta en el issue que vas a ocuparte — evita que dos personas hagan lo mismo.
  3. Haz un fork del repositorio y trabaja en una rama.
  4. Abre un pull request que haga referencia al número del issue.

Más de microsoft/graphrag

Todos los issues de microsoft/graphrag

Issues similares

Más issues de Python

Recibe los nuevos issues en tu correo

Un resumen breve de issues de GitHub para principiantes.