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
- Información general del Instrument.
- Definición del
os_signpostal que se asocia. - 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.
- Seleccionamos
Blankcomo plantilla - Comprueba que el profile es para iPhone XS y el proceso es Desappstre-CustomInstruments
- Pulsa sobre el botón de Grabar y ve al simulador de iPhone XS.
- Con nuestra app abierta, escribe el nombre de alguna serie y pulsa sobre el botón Search Shows
- 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
- Vídeo de la sesión 410 de la pasada WWDC 2018 sobre creción de Instruments personalizados
- Instruments Help Guide
- Instruments Developer Help
- Documentación oficial del API Logging
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.