Guía de Custom Instruments en Xcode

En esta guía aprenderás a crear tus propios Custom Instruments en Xcode 10 que te ayudarán a depurar tus proyectos de iOS, macOS… usando Instruments, la app que viene junto con Xcode,

Using Instruments, you can finally retire your print() statements, which are replaced with OSLog signposts and your own custom instruments.

Adios, print, adios

Desde los albores de los tiempos los desarrolladores hemos usando la función print para ir dejando un camino de migas de pan que seguir durante la ejecución de nuestros programas para ver dónde fallaban y tratar de averiguar el porque imprimiendo en el terminal el contenido de variables, estados de inicialización…

Después descubrimos los depuradores de código que venían con los primeros IDE y aquellos nos pareció una cosa fenómena. Podías para la ejecución en un punto determinado, ver en que estado se encontraba cada variables, ver la pila de llamadas, etc…

Y ahora Apple da una vuelta de tuerca y desde la versión 10 de Xcode podemos crear nuetros propios Instruments y además distruibuirlos para que otros desarrolladores puedan seguir las andanzas de nuestro código en Instruments de la misma forma en los que los ingenieros de Apple lo hacen.

You can go even further and build your own instrument with custom visualization and data analysis.

Porque efectivamente, esto mismo es lo que los desarrolladores de Apple hacen a diario en su trabajo.

Xcode includes templates so you can build instruments using the same tools that Apple uses.

Nos ponemos en situación

Acabo de terminar el desarrollo de un framework que conecta con el API de Trakt.TV, y me gustaría que el resto de programadores del proyecto pudieran trazar y medir la ejecución de esta librería una vez añadida a sus proyectos para que vean como interactua y que efectos tiene el código durante la ejecución.

Vamos a escribir en el log. OSLog

La primera clase con la que nos tenemos familiarizar es con OSLog que es un objeto de log personalizado que pasaremos a las funciones de logging que enviarán mensajes al sistema de logging.

La forma de crearlo es muy sencilla

Donde subsystem es un identificador único para el log, y nos servirá para filtrar y agrupar los mensajes que enviemos al sistema de logging. El papel de category es, como ya os imagináis, el de categorizar los mensajes dentro de nuestro log.

Pues ya estamos listos para escribir nuestro primer mensaje en el sistema de log, así que os presento a la función os_log.

Seguro que os habéis dado cuenta de dos detalles. Primero, que se puede indicar el tipo de mensaje que enviamos, y segundo, que podemos formatear los mensajes. Vamos a dedicarle un poco de tiempo a estos dos puntos.

Tipos de log

Están definidos por la estructura OSLogType, y podemos usar una de las cinco propiedades estáticas que nos brinda, que se corresponden con los cinco tipos de mensajes que existen.

Tipo ¿Cuándo se usa?
default Para situaciones en las que se podría dar un fallo
info Información para la fase de desarrollo o depuración, pero que quizá no sea esencial
debug Información que puede ser útil durante el desarrollo o la resolución de un problema
error Para los errores de nuestra aplicación
fault Para errores del sistema

Si os fijáis en los dos mensajes que hemos enviamos al sistema de logging veréis que son del tipo info ya que aportan poco al desarrollo y nada si estamos depurando un error.

Formateando los mensajes

Las plantillas de los mensajes personalizados se construyen de la misma manera en la que se hacía en la clase NSString, es decir, usando los String Format Specifiers. Algunos de los más útiles son…

Plantilla Tipo Ejemplo Resultado
%@ Objeto “Error en %@”, “parser” “Error en parser”
%d Int “Encontrados %d items”, 19 “Encontrados 19 items”
%f Double “Pi vale %d”, 3.14 “Pi vale 3.14”

Pero también podemos usar tipo predefinidos para mostrar por ejemplo, tamaños de archivos, velocidades de transmisión, fechas, etc…

Plantilla Tipo Ejemplo
%{time_t}d time_t 2018-11-06 17:24:13
%{errno}d errno Broken pipe
%{iec-bytes}d iec-bytes 2.64 MiB
%{bitrate}d bitrate 128 kbps
%{iec-bitrate}d iec-bitrate 112 Kibps

Encontraréis todos los tipos predefinidos en la sección Formatting Log Mesages de la documentación del framework os.

¿Y dónde veo estos mensajes?

Vas a usar una de las aplicación que vienen por defecto con macOS desde y que están dentro de la carpeta “Otros”, y me estoy refiriendo a Consola.

Como el proyecto de demostración corre en el simulador lo primero que hago es seleccionar iPhone Xs en la lista de Dispositivos de la lista que hay a la izquierda.

Una vez seleccionada verás como empiezan a salir mensajes de todo tipo en la ventana, pero como lo que queremos es ver los log de nuestra app lo que haremos será filtrar por el proceso, en este caso Desappstre-CustomInstruments, en la caja de texto de la parte superior.

Desde ese momento sólo verás los mensajes producidos por nuestra app, y entre ellos los que generamos nosotros.

OSSignpostID

Lo que acabamos de ver hasta ahora nos deja escribir entradas puntutales en el log, pero hay momentos en los que necesitamos saber cuando empieza y termina una tarea, por ejemplo, el tiempo empleado en recuperar las lista de serias más populares.

De nuevo los chicos de Cupertino vienen al rescarte en forma de función os_signpost. Esta función nos va a permitir añadir tres tipos nuevos de logs.

Tipo ¿Para qué sirve
begin Marca el inicio de un intervalo de tiempo
end Marca el final del intervalo de tiempo
event Señala un hecho relevante en nuestro código

Como desarrolladores nos interesa saber lo que tarda nuestro cliente de Trakt.TV en procesar la petición para las series más populares, así que vamos a añadir marcas de inicio y fin de petición en nuestra llamada.

Como podéis ver la función os_signpost también nos permite usar mensajes formateados exactamente igual que con os_log.

El inicio y final del periodo de tiempo se indica mediante el primer parámetro de la función. Como véis en la primera llamada usamos la opción .begin y en la última llamada usamos .end.

Otro parámetro igual o más importante es signpostID ya que sin él el sistema de logging sería incapaz de juntar un inicio de tiempo con su correspondiente final. Por eso lo primero que hemos hecho ha sido crear un OSSignpostID, que sería una especie de identificador único para los mensajes os_signpost y usarlo en las dos llamadas a la función.

Te preguntarás si estos logs también se ven en Consola. Mucho mejor, puedes verlos en Instruments. Para ello sólo tiene que arrancar el proyecto en modo Profile y cuando Instruments se abrá elige una plantilla en blanco.

Después dirígete al botón con el signo + situado en la esquina superior derecha y elige el tipo os_signpost.

Ve al simulador y haz algunas peticiones, verás cómo las llamadas a la función os_signpost que tenemos en el código aparecen en Instruments.

Para asegurarte de ver todos los mensajes generados ve al menú Acción de Consolas y marca las opciones para ver los mensajes de información y depuración.

Debugging like a Boss. Distribuye tus Instruments personalizados

Ya sacamos mensajes por Consola y nuestras trazas están disponibles a través de Instruments. Con esto el 99,9% de los desarrolladores quedaría satisfecho y contento.

Pero si eres de ese 0,1% que quiere ir un paso más allá todavía hay algo que puedes hacer para saltar al nivel Pro del debugging. Te estoy hablando de crear tu propio Instrument y distribuirlo junto con tu app/framework.

La forma de hacerlo es añadir un nuevo target al proyecto, concretamente tiene que ser para macOS y de tipo Instruments Package.

Cuando la hayas añadido dirígte a su carpeta y verás que únicamente contiene un archivo con extensión .instrpkg y cuyo contenido se parece al XML de forma sospechosa.

Y estás en lo cierto, a partir de este momento nos toca configurar el Custom Instrument añadiendo elementos distintos elementos que componen un Instrument, así que te recomiendo que le eches un vistazo a la documentación oficial.

Para nuestro ejemplo usaremos la plantilla del esquema os-signpost-interval-schema que sirve para construir Instruments a partir de mensajes os_signpost

Arriba verás el esqueleto sobre el que construir nuestra definición. Todos estos snippets están disponibles desde la librería de código de Xcode.

Cómo habéis podido ver en el código anterior la definición consta de tres partes bien diferenciadas

  1. Información general del Instrument.
  2. Definición del os_signpost al que se asocia.
  3. Como se presenta la información en el Instrument.

Vamos a ver qué nos podemos encontrar en cada una de ellas

Información

Es la más fácil de rellenar de todas. Sólo tenemos que poner un identificador único a nuestro Instrument, darle un nombre e indicarle quién es el creador.

También podemos indicar el número de versión o escribir una nota con información relevante sobre el Instrument.

Definición de os-signpost-interval-schema

Esta sección sirve, por decirlo de alguna manera, para que el Instrument sepa que os_signpost debe recuperar del logging del sistema.

Lo primero que hacemos es darle un identificador único y un nombre. Este identificador lo usaremos luego en otras secciones del archivo de definición.

Tras esto vienen la sección de casación. Aquí le vamos a decir al Instrument que OSLog y OSSignpostID debe capturar.

Comentar que se distingue entre mayúsculas y minúsculas y los valores deben ir entrecomillados.

Una vez que sabemos el òs_signpostque tenemos que capturar, nos toca decirle a Instrument qué mensajes son los que debe recoger. Para ello usamos las etiquetasstart-patternyend-pattern. En caso que los mensajes que genere nuestroos_signpost` utilice variables también tenemos que definir dichas variables en nuestro XML.

Vamos a ver cómo

Las fechas rojas establecen la relación entre los mensajes de inicio y fin mientras que las azules nos señalan las relaciones entre las variables que contienen los mensajes y su definición en el XML.

No puedo dejar de recordaros lo importante que es que nuestro mensaje definido en el XML coincida exactamente con el que definimos en nuestro código. En caso de diferir una mayúscula, un espacio en blanco hará que Instruments sea incapaz de recoger la información.

Voy a hacer una mención especial a la etiqueta column que es donde definimos las variables de los mensajes e indicamos el tipo al que pertenecen. Y por tipos de datos que no sea, puedes elegir entre 155 tipos diferentes, desde un string a un uint32 pasando por network-interface, sample-time, energy-impact o start-time…

Presentado en Instruments

La última de las secciones que nos quedan por definir para completar nuestros Instruments. En ella nos encargamos de relaciones los campos de os-signpost-interval-schema con lo que vamos a presentar en el interface de la aplicación Instruments.

La primera parte son datos de información sobre el Instrument es en la que creamos una etiqueta créate-table que es la base para el resto de etiquetas de esta sección

La etiqueta schema-ref debe tener el mismo valor que el de la etiqueta os-signpost-interval-schema//id.

Ahora le llega el turno a la etiqueta graph, donde vamos a decirle a Instruments qué y cómo debe mostrar la información en la parte superior (la de los gráficos, para entendernos)

La etiqueta table-ref debe tener el mismo valor instruments//create-table//id y en plato-template decimos por qué variable agrupamos la información y que valor debemos mostrar.

Y por último nos toca definir la manera en la que presentamos la información en la tabla inferior que hay en la aplicación Instruments.

Le damos un título con la etiqueta title y de nuevo la etiqueta table-ref debe tener el mismo contenido que el de la etiqueta instruments//create-table//id.

El resto de etiquetas column son eso, las columnas que tiene la tabla y que información presentamos, que pueden ser variables preferidas, como duration o start o variables definidas por nosotros en las secciones os-signpost-interval-schema//column

Viendo el resultado

Nuestro código envía mensajes al sistema de logging y hemos desarrollado nuestro propio Instrument. Ahora sólo que queda ver todo esto en acción.

Lo primero que tenemos que hacer es ejecutar la aplicación en el simulador para que quede instalada.

Después vamos a probar el Custom Imstrument, así que seleccionamos su target como esquema activo en Xcode y Mac como dispositivo donde ejecutarse.

Al ejecutarse veremos que se abre una instancia de Instruments con la peculiaridad de que su icono es de color gris en lugar del azulado de costumbre.

  1. Seleccionamos Blank como plantilla
  2. Comprueba que el profile es para iPhone XS y el proceso es Desappstre-CustomInstruments
  3. Pulsa sobre el botón de Grabar y ve al simulador de iPhone XS.
  4. Con nuestra app abierta, escribe el nombre de alguna serie y pulsa sobre el botón Search Shows
  5. Verás que en Instruments se verán las trazas de las búsquedas que realices.

O si lo prefieres mira el siguiente vídeo con todos los pasos que he referido anteriormente.

Para esta demostración el Custom Instrument sólo muestra información de la operación de búsqueda.

Código

Como siempre podéis descargar el proyecto asociado al artículo desde este repositorio de GitHub

Enlaces de interés

Conclusión

La depuración es inherente a la programación, y una parte fundamental en la resolución de los problemas que se pueden presentar en la fase de desarrollo como en la de producción.

Así que tener herramientas como Instruments y el API os pueden ayudarnos a mejorar la calidad de nuestros desarrollos y a resolver incidencias de producción más rapido.