Dart DevTools: Analizando el rendimiento de la aplicación con el CPU Profiler

Rastrear problemas de rendimiento en una base de código puede ser una tarea desalentadora. Hay múltiples formas de escribir código de Flutter de manera que se ejecute más lento de lo que debería. Algunas son obvias y otras son sutiles. Por ejemplo, quizás usaste la API o estructura de datos equivocada para una situación particular.

Este artículo recorre un caso de estudio simple examinando el rendimiento de una aplicación de interfaz de línea de comandos (CLI) de Dart lenta. Aprenderás sobre:

• Los profilers de CPU en general y su importancia.

• El profiler de CPU por muestreo que viene con Dart y Flutter.

Con esta nueva comprensión del profiling de CPU, depuraremos el rendimiento de nuestro programa. Lo haremos usando el CPU Profiler de Dart DevTools y la funcionalidad UserTag de dart:developer para localizar el código ineficiente. ¡Tenemos mucho que cubrir, así que vamos a empezar!

Nota: Dart DevTools también se conoce como Flutter DevTools, pero no debe confundirse con Chrome DevTools.

Considera la siguiente aplicación CLI de Dart sencilla:

​
// filename: grep.dart
import 'dart:io';
​
/// Finds and prints all instances of [pattern] in the [file].
void grep(File file, String pattern) {
  // Open the file and read its contents.
  final lines = file.readAsLinesSync();
​
  String output = '';
  int lineNum = 1;
  // Check each line to see if it matches `pattern`.
  for (final line in lines) {
    final matcher = RegExp(pattern);
    if (matcher.hasMatch(line)) {
      final foundMessage = '$lineNum:$line';
      output += foundMessage;
    }
    lineNum++;
  }
  stdout.writeln(output);
}
​
void main(List<String> arguments) {
  if (arguments.length != 2) {
    print('Usage: dart grep.dart <path> <pattern>');
    exitCode = 64;
    return;
  }
  final path = arguments[0];
  final pattern = arguments[1];
​
  final file = File(path);
  if (!file.existsSync()) {
    stderr.writeln("Error: unable to open file '$path'");
    exitCode = 64;
    return;
  }
​
  grep(file, pattern);
}

El programa grep.dart implementa una versión de la común herramienta de Unix. Permite a los usuarios buscar en archivos la aparición de una cadena de caracteres que coincida con un patrón especificado. Por ejemplo, dado un archivo names.txt que contiene:

$ cat names.txt
Frank
Bob
Franny
June
Ben
Francis

Encontremos todas las líneas que contienen la cadena 'Fran':

$ dart grep.dart names.txt 'Fran'
1:Frank
3:Franny
6:Francis

¡Excelente! Deberíamos esperar esta salida de grep. Dicho esto, names.txt es un archivo pequeño. Intentemos encontrar todas las instancias de 'Hummingbird' en un documento de texto más grande. ¿Qué pasaría si ejecutáramos el mismo programa en un archivo de 437.000 líneas y 147 MiB sobre colibríes?

$ dart grep.dart hummingbird_encyclopedia.txt 'Hummingbird'

Vaya… no termina, ni siquiera después de dos minutos. ¿Cómo le va a grep de Unix?

$ grep -n 'Hummingbird' hummingbird_encyclopedia.txt
16:'''Hummingbirds''' are [[bird]]s native to the…
22:Hummingbirds have the highest…
24:Hummingbirds split from their [[Sister taxon|sister group]]…
// Output continues

El grep de Unix buscó en todo el archivo y devolvió todas las líneas que contienen Hummingbird en unos 45 segundos. Claramente hay algo extraño en nuestro código que deberíamos investigar. Pero ¿cómo podemos identificar la causa de nuestros problemas de rendimiento? El CPU Profiler que viene con Dart DevTools es un buen lugar para empezar.

Las herramientas de profiling de CPU rastrean dónde pasa su tiempo un programa durante la ejecución. Para ofrecer la experiencia de profiling de CPU más eficiente computacionalmente, la máquina virtual de Dart (Dart VM), que impulsa las aplicaciones CLI de Dart y Flutter, usa un profiler de CPU por muestreo. Cuando se usa con herramientas como Dart DevTools, puedes identificar cuellos de botella de rendimiento en programas de Dart.

Un profiler de CPU por muestreo toma un enfoque estadístico para recopilar datos de rendimiento de la aplicación. Recopila muestras interrumpiendo hilos a intervalos regulares y tomando una instantánea de la pila de llamadas actual y otro estado de ejecución relevante. Estas muestras pueden procesarse para obtener información sobre aproximadamente cuánto tiempo se pasa ejecutando funciones específicas y con qué frecuencia aparecen las funciones en diferentes pilas de llamadas.

La frecuencia con la que se recopilan las muestras se conoce como tasa de muestreo y se mide en muestras por segundo (también conocido como hercios o Hz). La mayoría de los profilers de muestreo tienen tasas de muestreo de 1000 Hz o superior. Las tasas de muestreo más altas resultan en perfiles de CPU más detallados, a expensas de una mayor sobrecarga de muestreo en el proceso objetivo. Con tasas de muestreo razonables, los profilers de CPU por muestreo son eficientes y tienen poco o ningún impacto en las características de rendimiento de la aplicación analizada. Como beneficio adicional, los datos recopilados suelen ser menos costosos computacionalmente de procesar para su análisis en comparación con los profilers de trazado.

Esta sección entra en detalle sobre cómo funciona el profiler de CPU por muestreo de la Dart VM. No necesitas conocer estos detalles al analizar perfiles de CPU. Si no te interesan los detalles técnicos del profiler de CPU por muestreo, salta esta sección.

El profiler de CPU por muestreo de la Dart VM tiene tres componentes importantes: el interrumpidor de hilos, el recopilador de muestras y el procesador de muestras.

El interrumpidor de hilos se ejecuta en un hilo dedicado y dispara la recopilación de muestras de CPU en cada hilo que gestiona la VM. El interrumpidor de hilos normalmente está inactivo, despertándose solo una vez por intervalo de muestreo. Después de cada intervalo de muestreo, el interrumpidor recorre la lista de hilos, informando a cada hilo que debe pausarse y recopilar una muestra. El interrumpidor de hilos tiene un comportamiento ligeramente diferente en distintas plataformas debido a detalles específicos del sistema operativo.

En la mayoría de las plataformas que soportan control de flujo basado en señales (Android y Linux), la señal SIGPROF se envía a cada hilo. Esto dispara una interrupción que invoca un manejador de señales registrado por el profiler de CPU en el hilo objetivo, que luego recopila la muestra de CPU antes de reanudar su trabajo.

En otras plataformas que no soportan señales (Windows y Fuchsia) o que tienen un rendimiento pobre en algunas situaciones al usar SIGPROF (MacOS e iOS), el interrumpidor de hilos usa llamadas al sistema para pausar y reanudar explícitamente cada hilo después de recopilar la muestra de CPU. En este caso, la recopilación de muestras se hace en el hilo del interrumpidor de hilos en lugar de en el hilo que se está muestreando.

Una vez que un hilo ha sido interrumpido, el profiler de CPU recopila una muestra del estado de ejecución actual del hilo. Cada muestra incluye metadatos como:

• identificadores de hilo e isolate

• etiqueta de usuario activa para el hilo

• marcas de tiempo de recopilación

• stack trace actual del hilo muestreado

El stack trace recopilado consiste en una lista de contadores de programa (PCs), que corresponden a las direcciones de retorno de cada función de Dart y nativa encontrada en la pila. Estos PCs se recopilan mediante un proceso conocido como “recorrer la pila”. Al realizar un recorrido de pila, el recorrido de pila usa el puntero de marco (FP) del marco superior y la disposición conocida de cada marco de pila para encontrar y registrar el PC asociado con la función, así como el FP del marco de pila anterior. El recorrido de pila repite este proceso, usando el FP del marco anterior como punto de partida, hasta que llega al final de la pila, como se muestra en la Figura 1.

Cada muestra recopilada se almacena en el búfer de muestras de la VM, un búfer circular que puede almacenar un número limitado de muestras de CPU. Esto permite a la VM evitar la necesidad de asignaciones adicionales en tiempo de ejecución, lo que puede impactar negativamente en el rendimiento o causar problemas si se hace en el manejador de señales.

El tamaño del búfer de muestras se fija en tiempo de ejecución y, una vez lleno, las muestras antiguas serán sobrescritas con nuevas muestras por el profiler. La velocidad a la que se llena el búfer de muestras depende de la tasa de muestreo y de la profundidad promedio de pila de cada muestra. Por ejemplo, tasas de muestreo más altas y pilas más profundas hacen que el búfer se reinicie más rápidamente. En DevTools, los desarrolladores pueden controlar la rapidez con la que el búfer de muestras se reinicia eligiendo entre tasas de muestreo bajas (1000 Hz), medias (4000 Hz) y altas (20.000 Hz).

Cuando un cliente envía una solicitud de un perfil de muestras de CPU a través del protocolo de servicio de la VM, el profiler de CPU necesita procesar las muestras recopiladas antes de enviarlas al cliente. El profiler:

1. Recorre el búfer de muestras, usando filtros para recuperar solo las muestras del isolate y el período de tiempo especificados por el cliente.

2. Simboliza, o mapea los PCs a nombres de funciones, cada marco de pila en el conjunto de muestras.

3. Serializa todo el búfer de muestras procesado a JSON.

4. Envía el JSON de vuelta al cliente.

Incluso después del procesamiento realizado por el profiler, la respuesta de muestras de CPU es de bajo nivel y requiere procesamiento adicional por parte de las herramientas de desarrollo para ser útil. Por ejemplo, Dart DevTools puede convertir la lista de muestras de CPU en varias representaciones estructurales que permiten identificar funciones costosas (Bottom Up) y rutas de llamadas costosas (Call Tree y CPU Flame Chart), e inspeccionar estadísticas de llamantes y llamadas (Method Table) para métodos individuales.

Ahora que estás familiarizado con qué son los profilers de CPU por muestreo y cómo funcionan, depuremos el rendimiento de nuestra implementación de grep. Ejecutemos el código de nuevo con --observe y abramos la pestaña CPU Profiler de Dart DevTools:

Note: You don’t need to use the --observe flag when testing a Flutter app in DevTools.

$ dart — observe grep.dart hummingbird_encyclopedia.txt 'Hummingbird'
The Dart VM service is listening on http://127.0.0.1:8181/omxEtsCtW9k=/
The Dart DevTools debugger and profiler is available at: http://127.0.0.1:8181/omxEtsCtW9k=/devtools?uri=ws://127.0.0.1:8181/omxEtsCtW9k=/ws
// At this point, the terminal hangs with no output.

¡Vaya! De todas las muestras recopiladas en un período de 11,6 segundos, el isolate pasó más del 90% de su tiempo de CPU ejecutando _StringBase.+. Es probable que esto esté relacionado con nuestros problemas de rendimiento, pero puede que no sea obvio qué bloque de código en nuestra función grep es la fuente de la lentitud. Afortunadamente, podemos acotar aún más la ubicación de las llamadas costosas a _StringBase.+ usando etiquetas de usuario.

Cuando el profiler de CPU de Dart interrumpe un hilo para recopilar una nueva muestra, registra la etiqueta de usuario actual establecida para el isolate. La librería dart:developer proporciona la clase UserTag que te permite especificar y establecer etiquetas personalizadas para secciones de código que te interesa perfilar.

Para entender mejor dónde estamos pasando tiempo en nuestra implementación de grep, podemos instrumentar la función con etiquetas de usuario:

// filename: grep.dart
import 'dart:developer';
import 'dart:io';
​
/// Finds and prints all instances of [pattern] in the [file].
void grep(File file, String pattern) {
  final defaultTag = getCurrentTag();
  final fileReadTag = UserTag('File Read');
  final textMatchTag = UserTag('Text Matching');
  final printTag = UserTag('Print Output');
​
  // Set the 'File Read' tag as the current user tag.
  fileReadTag.makeCurrent();
​
  // Open the file and read its contents.
  final lines = file.readAsLinesSync();
​
  // Set the 'Text Matching' tag as the current user tag.
  textMatchTag.makeCurrent();
  String output = '';
  int lineNum = 1;
  // Check each line to see if it matches `pattern`.
  for (final line in lines) {
    final matcher = RegExp(pattern);
    if (matcher.hasMatch(line)) {
      final foundMessage = '$lineNum:$line';
      output += foundMessage;
    }
    lineNum++;
  }
​
  // Set the 'Print Output' tag as the current user tag.
  printTag.makeCurrent();
  stdout.writeln(output);
​
  // Reset the user tag to the tag set when grep was invoked.
  defaultTag.makeCurrent();
}

Ahora, volvamos a ejecutar nuestro programa y abramos el CPU Profiler. Para ver nuestro perfil categorizado, selecciona la opción Group by: User Tag del menú desplegable:

Cuando expandimos la etiqueta Text Matching, confirmamos que el método _StringBase.+ se llama en nuestro bucle de coincidencia de texto:

Con esta información, deberíamos poder echar un vistazo más de cerca a nuestro código e identificar el problema:

  // Set the ‘Text Matching’ tag as the current user tag.
  textMatchTag.makeCurrent();
  String output = '';
  int lineNum = 1;
  // Check each line to see if it matches `pattern`.
  for (final line in lines) {
    final matcher = RegExp(pattern);
    if (matcher.hasMatch(line)) {
      final foundMessage = '$lineNum:$line';
      // Ahah! This is our call to _StringBase.+!
      output += foundMessage;
    }
    lineNum++;
  }

¡Ahí está! Hemos cometido el error clásico de añadir contenido a un String múltiples veces en lugar de usar un StringBuffer. Añadir contenido a un String crea un nuevo string para almacenar el resultado del método _StringBase.+. Como resultado, copiamos output + foundMessage en un nuevo string cada vez que encontramos una coincidencia.

A medida que output se hace más largo, añadir datos se vuelve más costoso, tomando O(m*n) para realizar las copias, donde m es el número promedio de caracteres en una coincidencia y n es el número total de caracteres en el string final. Si usamos un StringBuffer, no copiamos output cada vez que le añadimos contenido, sino que concatenamos las coincidencias en una sola operación O(n) al final de la función.

Ahora que nuestra app usa StringBuffer.writeln en lugar de añadir a un String, veamos nuestra función:

// filename: grep.dart
import ‘dart:developer’;
import 'dart:io';
​
/// Finds and prints all instances of [pattern] in the [file].
void grep(File file, String pattern) {
  final defaultTag = getCurrentTag();
  final fileReadTag = UserTag(‘File Read’);
  final textMatchTag = UserTag(‘Text Matching’);
  final printTag = UserTag(‘Print Output’);
​
  // Set the ‘File Read’ tag as the current user tag.
  fileReadTag.makeCurrent();
​
  // Open the file and read its contents.
  final lines = file.readAsLinesSync();
​
  // Set the ‘Text Matching’ tag as the current user tag.
  textMatchTag.makeCurrent();
  final output = StringBuffer();
  int lineNum = 1;
  // Check each line to see if it matches `pattern`.
  for (final line in lines) {
    final matcher = RegExp(pattern);
    if (matcher.hasMatch(line)) {
      final foundMessage = '$lineNum:$line';
      // Add the match to the buffer without creating a copy.
      output.writeln(foundMessage);
    }
    lineNum++;
  }
​
  // Set the ‘Print Output’ tag as the current user tag.
  printTag.makeCurrent();
  // output.toString() concatenates each entry in the buffer
  // into a new String, only performing a single allocation of
  // size `output.length`.
  stdout.writeln(output);
​
  // Reset the user tag to the tag set when grep was invoked.
  defaultTag.makeCurrent();
}

Ejecutemos nuestra prueba de nuevo para ver si hay alguna mejora:

$ dart grep.dart hummingbird_encyclopedia.txt 'Hummingbird'
16:‘’’Hummingbirds’’’ are [[bird]]s native to the…
22:Hummingbirds have the highest…
24:Hummingbirds split from their [[Sister taxon|sister group]]…
// Output continues

Usando StringBuffer, podemos encontrar todas las instancias de 'Hummingbird' en unos 45 segundos. ¡Eso está mucho mejor y casi igual que la implementación de grep de Unix! Echemos otro vistazo al profiler de CPU para ver si podemos mejorar el rendimiento aún más:

Un vistazo rápido al perfil nos dice que pasamos la mayor parte del tiempo imprimiendo coincidencias y que la coincidencia real solo toma unos 200ms. Deberíamos centrarnos en el código que cae bajo la etiqueta 'Print Output':

  // Set the ‘Print Output’ tag as the current user tag.
  printTag.makeCurrent();
  // output.toString() concatenates each entry in the buffer
  // into a new String, only performing a single allocation of
  // size `output.length`.
  stdout.writeln(output);

No parece que haya mucho que podamos hacer ya que solo estamos haciendo una única llamada a stdout.writeln, un miembro de la librería central dart:io. Mirando el CPU flame chart en el profiler, vemos que este código está en el SDK y que no podemos obtener más mejoras de rendimiento en nuestro código.

¡Con esto, hemos terminado!

Hemos logrado mucho desde el principio de este artículo. Nosotros:

• Escribimos una herramienta grep sencilla en Dart.

• Identificamos que nuestro programa tenía un rendimiento pobre.

• Aprendimos sobre profilers de CPU y exploramos el profiler de CPU por muestreo de la Dart VM.

• Usamos el CPU Profiler de Dart DevTools para identificar y arreglar los problemas de rendimiento de nuestro programa.

Tener un buen conocimiento de las herramientas de rendimiento es una habilidad importante y, como hemos mostrado en este artículo, puede ayudarte a identificar problemas de rendimiento potencialmente sutiles en tu código. El CPU Profiler es solo una de las muchas herramientas que vienen con Dart DevTools que pueden ayudarte a entender mejor el comportamiento y el rendimiento de tus aplicaciones CLI de Dart y Flutter.

En futuros artículos, exploraremos otras formas de usar Dart DevTools para depurar y optimizar tus apps, incluyendo:

• Analizar el uso de memoria a través de la pantalla de Memory

• Examinar las líneas de tiempo de ejecución a través de la pantalla de Performance

• Inspeccionar el tráfico HTTP a través de la pantalla de Network

¡Hasta entonces, feliz hacking!

Si te apetece, sígueme en GitHub para estar al día con mi trabajo en Flutter y la máquina virtual de Dart, así como con otros proyectos paralelos.