En el artículo anterior, cubrimos la arquitectura de la sBPF VM, las convenciones de los registros y el conjunto de instrucciones. Ahora analizaremos la ejecución real del bytecode utilizando la agave-ledger-tool (una herramienta CLI que viene con la cadena de herramientas de Solana) para generar trazas de ejecución y calcular manualmente las unidades de cómputo consumidas por un programa.
Aunque rastrear los opcodes manualmente es todo un reto, podemos generar automáticamente una traza visual de cómo se actualizó cada registro con la ejecución de cada opcode. Esto nos permite ver exactamente qué instrucciones se ejecutan y cómo se acumulan las unidades de cómputo.
Análisis de un Programa Simple
Analicemos el bytecode de un programa Anchor simple para ver cómo cada parte se convierte en instrucciones SBF y cómo utilizan los registros. Esto también nos permitirá calcular manualmente el costo en unidades de cómputo.
Configuración del Proyecto
Primero, inicializa un nuevo proyecto con:
anchor init compute_unit
cd compute_unit
Reemplaza el código en programs/compute_unit/src/lib.rs con el programa mínimo a continuación. Usamos una función initialize vacía para poder centrarnos en medir los costos de cómputo base sin ninguna lógica de negocio:
use anchor_lang::prelude::*;
declare_id!("CR33kP6d39mBZv1ryjufVXoRm6djnWW8uKoQXwU5kgDV");
#[program]
pub mod compute_unit {
use super::*;
pub fn initialize(ctx: Context<Initialize>) -> Result<()> {
Ok(())
}
}
#[derive(Accounts)]
pub struct Initialize {}
Ejecutaremos la función initialize en un validador local (veremos cómo a medida que avancemos) y usaremos solana logs para ver las unidades de cómputo que consume. Luego desensamblaremos el programa y generaremos una traza de ejecución para observar qué opcodes SBF se ejecutaron. Al hacerlo, podremos calcular manualmente cómo cada instrucción se suma al costo total de unidades de cómputo.
Construye e inicia un validador local:
anchor keys sync
anchor build
Luego, en una nueva terminal:
solana-test-validator
Esto inicia un validador local y crea un directorio test-ledger/—agave-ledger-tool usa este directorio para cargar el estado del ledger al generar trazas del programa.
Ejecuta solana logs en otra terminal, y luego ejecuta anchor test --skip-local-validator en una terminal separada para ver exactamente cuántas unidades de cómputo usa la función initialize. Si hacemos esto, obtenemos 272 unidades de cómputo. Volveremos a esto más adelante.
Desensamblado del Programa
El primer paso en el análisis del bytecode de Solana es convertir el binario ejecutable del programa de Solana (generalmente almacenado en un archivo target/deploy/<project_name>.so) en mnemónicos de bytecode que podamos entender un poco mejor. Los mnemónicos son simplemente una representación legible por humanos de opcodes binarios/hexadecimales. P. ej., en la EVM, 0x60 = PUSH1, 0x52 = MSTORE, etc.
Necesitamos una carpeta test-ledger en la raíz del proyecto que contenga un archivo genesis.bin. El solana-test-validator que ejecutamos antes los genera automáticamente. La agave-ledger-tool (parte de la cadena de herramientas de Solana) utiliza este archivo para cargar el estado del ledger al desensamblar programas.
Ahora podemos desensamblar nuestro programa con:
agave-ledger-tool program --ledger test-ledger disassemble target/deploy/compute_unit.so --output json > output.txt
Esto vuelca los mnemónicos de ensamblador en output.txt. Verás algo como esto:
function_0:
mov64 r0, r2
and64 r0, 1
jeq r0, 0, lbb_32
mov64 r0, 0
jslt r5, 0, lbb_34
stxdw [r10-0x8], r3
jeq r5, 0, lbb_41
...
...
Las etiquetas como function_0: son destinos de salto en el bytecode a los que otras instrucciones pueden saltar usando la instrucción call. Las funciones de Rust se compilan en secuencias de instrucciones y el compilador genera estas etiquetas para marcar las entradas de las funciones o los bloques de código internos. Así que cuando ves algo como call function_11561, la ejecución salta a ese desplazamiento (offset) en el bytecode y ejecuta las instrucciones que hay allí.
Estos son los mnemónicos de nuestro programa de Solana. Sin embargo, no podemos hacer mucho con esto, es muy grande y extremadamente difícil de analizar manualmente.
Generación de una Traza de Ejecución
Para generar una traza, necesitamos decirle a la agave-ledger-tool qué función debe llamar en nuestro programa. Hacemos esto creando un archivo instructions.json, que le pasaremos a la herramienta como verás en breve.
Ahora, crea un archivo instructions.json en la carpeta raíz del proyecto y pega el código a continuación:
{
"accounts": [],
"program_id": <program_id>,
"instruction_data": [175, 175, 109, 31, 13, 152, 155, 237]
}
Los parámetros anteriores indican: la lista de accounts (vacía aquí ya que nuestra función initialize no toma ninguna cuenta), el program_id a invocar (reemplaza <program_id> con el ID real de tu programa) y los datos de la instrucción.
El campo instruction_data contiene únicamente el discriminador de 8 bytes para la función initialize (sin argumentos adicionales ya que nuestra función no recibe ninguno). Anchor genera estos discriminadores tomando los primeros 8 bytes de sha256("<namespace>:<function_name>"). En nuestro caso, eso es sha256("global:initialize"). El namespace es global porque nuestro programa está contenido en el alcance (scope) más externo de nuestro código base.
Ahora generemos la traza:
agave-ledger-tool program run target/deploy/compute_unit.so --limit 200000 --trace trace.txt --ledger test-ledger --input instructions.json
Esto ejecuta el programa con los datos de nuestra instrucción (la función initialize) y genera la salida de la traza de ejecución en trace.txt.0. La bandera --limit establece un límite de unidades de cómputo. No es obligatoria, pero resulta útil para realizar pruebas.
Nota: Si obtienes un error que dice Err(JitNotCompiled) (por ejemplo, al usar una MacBook ARM), añade --mode interpreter a tu comando para usar el modo de intérprete en lugar del modo de compilación JIT predeterminado.
Lectura de la Traza de Ejecución
El archivo trace.txt.0 se ve así. Hemos etiquetado cada sección para mayor claridad y solo mostramos las primeras 6 instrucciones:
Esto nos da suficiente información para analizar y entender el programa y las unidades de cómputo que consumió.
Veamos qué muestra cada columna:
- Columna de conteo de ejecución (primera columna): El contador de ejecución.
- Columnas con prefijo r (columna 2-12): Muestra el estado/valor de cada uno de los 11 Registros de la VM de Solana (r0 - r10) después de que se ejecutara la instrucción sobre él.
- Columna de contador de programa (columna 13): El Contador de Programa (PC) o índice de la instrucción/opcode dada en el binario del programa.
- Columna de instrucción (columna 14): La instrucción/opcode y sus operandos a ejecutar a continuación.
Ahora repasemos las primeras 6 instrucciones de la salida de la traza para familiarizarnos con cómo cambian los valores en los registros durante la ejecución. Vamos a dividir la imagen para que los valores de los registros sean más visibles:
- La primera instrucción (
mov64 r2, r1) copia el valor de 64 bits del registro 1 al registro 2. En la siguiente fila, tanto r1 como r2 contienen el mismo valor. - La segunda instrucción (
mov64 r1, r10) copia el valor del registro 10 al registro 1. - La tercera instrucción (
add64 r1, -72) resta 72 del valor en r1 y almacena el resultado nuevamente en r1. - La cuarta instrucción (
call function_11561) salta a otra función; la ejecución se reanuda después de la llamada cuando la función retorna. - La quinta instrucción (
mov64 r8, r1) copia el valor del registro 1 al registro 8 (dentro de la función llamada, como se muestra en el cambio del PC. El PC pasó de 3443 a 11561 debido a esta llamada de función). - La sexta instrucción (
stxdw [r10-0x30], r2) almacena 64 bits del registro 2 en la memoria, en la dirección indicada por r10 menos el offset de memoria 0x30. Dado que, en esta sexta ejecución, el registro 2 contiene el valor0x0000000400000000y el registro 10 contiene el valor0x0000000200003000, esto significa que la instrucción almacenará el valor de 64 bits0x0000000400000000en la dirección de memoria0x0000000200002FF0(que esr10 - 0x30, donde r10 calcula una nueva dirección a partir de la dirección almacenada en r10 menos ese offset especificado).
Cálculo de las Unidades de Cómputo
Ahora que hemos visto cómo se muestra la traza de ejecución y qué indica cada columna, la siguiente pregunta es: ¿dónde entran en juego las unidades de cómputo aquí?
Cada instrucción sBPF cuesta 1 unidad de cómputo. Sin embargo, las instrucciones syscall incurren en cargos adicionales que varían según el tipo. Unidades de cómputo totales = conteo de instrucciones + cargos de las instrucciones syscall.
Veamos esto en acción. En el mismo programa, si nos desplazamos hacia abajo hasta el final de la traza de ejecución (en el archivo trace.txt.0), podemos ver que el último conteo/índice de ejecución es 171, lo que significa que este programa ejecutó 172 instrucciones (índice 0-171). Los logs del validador para la misma llamada (que se muestran a continuación) informan que se consumieron 272 unidades de cómputo.
La diferencia (100) proviene de la syscall de registro (logging) que imprime el nombre de la instrucción (“Program log: Instruction: Initialize”).
Esa syscall es sol_log_, que cobra un syscall_base_cost de 100 unidades de cómputo (en el momento de escribir este artículo). Ahora, si sumamos esto al recuento de 172 instrucciones, obtenemos 172 + 100 = 272 unidades de cómputo en total.
Podemos verificar esto buscando el opcode syscall en nuestro archivo trace.txt.0. Aparece una vez — syscall sol_log_ en el conteo de ejecución 157.
¿Por qué el PC no empieza en 0?
A diferencia del bytecode de la EVM, donde la ejecución comienza en el primer PC, en el bytecode de Solana, la ejecución comienza donde sea que se encuentre la etiqueta de salto entrypoint (discutiremos esto en el siguiente tutorial, pero puedes buscar <entrypoint> en el archivo output.txt que generamos antes para verlo). El runtime de Solana salta directamente a esta etiqueta al invocar tu programa. Si observas la imagen anterior que muestra nuestra traza de ejecución, verás que la primera instrucción mov64 r2, r1 se encuentra en un PC distinto de cero (3440 en esta traza) en lugar del PC 0. Esto significa que el bytecode desde el PC 0 hasta el PC 3439 existe en el programa compilado, pero no se ejecuta a menos que se salte a él explícitamente.
¿Qué hay en esa sección omitida? Contiene otros bloques de código etiquetados (como funciones auxiliares, rutinas de manejo de errores o código generado por Anchor) que solo se ejecutan cuando se salta a ellos desde la ruta de ejecución principal. Si buscas la etiqueta <entrypoint> en output.txt (el volcado completo del bytecode), verás que está definida en el offset 3440, con otras etiquetas como function_0, function_11561, etc., definidas antes en offsets anteriores. El runtime comienza la ejecución en <entrypoint> y luego salta a estas otras etiquetas según sea necesario (puedes ver call function_11561 en la traza de arriba). Nuevamente, discutiremos el punto de entrada (entrypoint) en el próximo tutorial.
¿De dónde proviene el log si el programa no registra nada desde su código?
Hemos visto que nuestro programa consume unidades de cómputo tanto de la ejecución de instrucciones como de los costos de los syscalls. Para entender esto mejor, primero identificaremos de dónde proviene el registro (log) en nuestra traza, y luego agregaremos registros explícitos para ver cómo diferentes syscalls afectan el conteo total de unidades de cómputo. Esto nos permitirá verificar nuestra fórmula (instrucciones + costos de syscall = total de CU) con números concretos.
¿Qué está intentando registrar el programa con el syscall sol_log_? Para averiguarlo, ejecutemos una prueba contra nuestro validador de prueba con los logs de Solana en ejecución. (Si ya tienes esto en ejecución, puedes omitir este paso):
# start up a test validator
solana-test-validator
# get solana logs running in a separate terminal
solana logs
Ejecuta anchor test --skip-local-validator en una terminal separada. Deberíamos ver algunas cosas registradas en la terminal de logs de Solana y el último log nos da la respuesta. Los logs de un programa se pueden identificar por tener una clave Program log: debajo de la sección Log Messages: de esa transacción.
En el ejemplo anterior, la salida de la transacción que involucra estrictamente la llamada a initialize es esta:
Observándolo, tiene tres propiedades:
- Signature: que es la firma del firmante.
- Status: si la transacción fue exitosa.
- Log Messages: logs de esa llamada en particular.
Lo que nos interesa es la sección Log Messages de la salida de log anterior. También tiene algunas propiedades:
- La primera línea nos dice el ID del programa que se está invocando y su profundidad de invocación, empezando desde 1.
- La penúltima línea nos indica la cantidad de unidades de cómputo que consumió nuestro programa y la unidad de cómputo máxima establecida para esa transacción.
- La última línea nos dice si la llamada fue exitosa.
- Todo lo que está en medio (en este caso, solo una línea) son los logs reales del programa. Estos se pueden identificar fácilmente ya que siempre comienzan con
Program xxx:dondexxxpuede variar dependiendo de la syscall que se utilice para registrar el mensaje.
En nuestro caso anterior, tenemos un log que simplemente nos dice el nombre de la instrucción de nuestro programa o, en otras palabras, la función a la que llamamos. Este log es insertado automáticamente por Anchor. Nuestro código de programa no llama explícitamente a ninguna función de log, pero la expansión de macros de Anchor agrega un syscall sol_log_ que imprime “Instruction: Initialize” cuando la función se ejecuta. Si escribieras el mismo programa en Rust nativo sin Anchor, no verías este log a menos que lo agregaras explícitamente.
Dado que Anchor registra automáticamente el nombre de la instrucción para cada llamada de función, cada invocación de programa de Anchor tendrá al menos una línea de log (el nombre de la instrucción).
Agregando logs explícitos para ver los costos de los syscalls
Ahora agreguemos nuestra propia llamada de registro (log) para ver cómo múltiples syscalls afectan el conteo. Agrega solana-program = "1.18.17" a programs/compute_unit/Cargo.toml como dependencia y actualiza el código de nuestro programa a lo siguiente:
use anchor_lang::prelude::*;
use solana_program::log::sol_log_compute_units;
declare_id!("CR33kP6d39mBZv1ryjufVXoRm6djnWW8uKoQXwU5kgDV"); // Run anchor sync to update your program ID
#[program]
pub mod compute_unit {
use super::*;
pub fn initialize(ctx: Context<Initialize>) -> Result<()> {
sol_log_compute_units();
Ok(())
}
}
#[derive(Accounts)]
pub struct Initialize {}
Al ejecutar las pruebas para esto, podemos ver que el solana log de nuestra transacción se mostrará de la siguiente manera:
Podemos ver que ahora tenemos 2 logs Program xxx:. El primero es nuestro log habitual Instruction: Initialize, y el segundo muestra cuántas unidades de cómputo restan en el punto en el que se llamó a sol_log_compute_units().
A partir del log, también vemos que quedan 199,641 unidades de cómputo cuando se ejecuta sol_log_compute_units(). Al restar este valor del límite de unidades de cómputo (200,000), obtenemos 359 unidades de cómputo consumidas para llegar a ese punto. Desglosaremos esto y verificaremos a dónde fueron a parar esas 359 unidades.
Nota: Al registrar las unidades de cómputo restantes, el formato siempre es Program consumption: X units remaining.
Desglose del cálculo de unidades de cómputo
Después de agregar sol_log_compute_units() a nuestro programa y generar una nueva traza (puedes hacerlo como lo hicimos antes). Desde trace.txt.0:
- El conteo de ejecución es 0-172 (173 instrucciones totales ejecutadas, frente a las 172 en nuestra traza anterior sin registro adicional).
- El conteo de ejecución 157 tiene
syscall sol_log_(esto registra “Instruction: Initialize”). - El conteo de ejecución 158 tiene
syscall sol_log_compute_units_(esto registra las CU restantes).
Puedes buscar esto por ti mismo en trace.txt.0 (sol_log_ y sol_log_compute_units_) para confirmar dónde aparecen en la salida de la traza.
Aquí es donde se pone interesante. Cada syscall tiene un cargo de runtime. Los syscalls deben tener estos cargos para evitar que los programas se ejecuten por siempre (si los syscalls fueran gratuitos, un programa podría hacer bucles infinitos de syscalls y congestionar la red):
sol_log_cuesta 100 CU (definido porsyscall_base_costaquí).sol_log_compute_units_también cuesta 100 CU (definido porget_remaining_compute_units_costaquí).
Por lo tanto, el total de unidades de cómputo consumidas:
Instructions executed: 173
Runtime syscall charges: 200 (100 + 100)
---
Total compute units: 373
Esto coincide con lo que muestran los logs del validador: “consumed 373 of 200000 compute units”.
Verificación de unidades de cómputo en el punto de registro
Recuerda que el log mostraba “199641 units remaining” cuando se ejecutó sol_log_compute_units(). Eso significa que se consumieron 359 unidades hasta ese punto (200,000 - 199,641 = 359).
Verifiquemos que esto tenga sentido. Al observar la traza, sol_log_compute_units_ aparece en el conteo de ejecución 158, lo que significa:
- 159 instrucciones ejecutadas hasta ahora (conteo de ejecución 0-158).
- Un cargo de 100 CU por la primera syscall
sol_log_(en el conteo de ejecución 157). - Un cargo de 100 CU por la propia
sol_log_compute_units_(aplicado cuando se ejecuta). - Total: 159 + 100 + 100 = 359 CU
¡Perfecto! Esto confirma que nuestra traza nos muestra exactamente cuándo ocurre cada syscall y cómo se acumulan las unidades de cómputo a lo largo de la ejecución.
Observación del manejo de parámetros en la traza
Reemplacemos solana_program::log::sol_log_compute_units(); de nuestro programa actual y sustituyámoslo por solana_program::log::sol_log_64(1, 2, 3, 4, 5);. Aquí, en cambio, estamos registrando cinco números de 64 bits con un syscall.
Al ejecutar nuestra prueba ahora, podemos ver nuestros logs relevantes como:
Efectivamente tenemos 2 logs. Nuestro log habitual del nombre de la instrucción y, como era de esperar, nuestros 5 números registrados.
Si ejecutamos nuestro comando de traza de ejecución y buscamos syscall en trace.txt.0, encontramos dos entradas. La segunda es un syscall a sol_log_64_, que coincide con lo que acabamos de hacer.
El código base de las unidades de cómputo de Solana muestra que log_64_units cuesta 100 unidades, lo mismo que get_remaining_compute_units_cost. Pero ten en cuenta que esto cuesta 5 unidades de cómputo adicionales (ya no 373 como antes, sino 378). Eso se explica fácilmente por el hecho de que justo antes del syscall a sol_log_64_, tenemos 5 instrucciones nuevas. Mostramos esto a continuación.
Una vez más, las imágenes están divididas para hacer más visibles los valores de los registros:
Esto se explica por sí mismo. En la imagen, vemos cinco instrucciones mov que almacenan cinco números en los registros r1-r5. Esos números son exactamente lo que registramos.
Este artículo es parte de una serie de tutoriales sobre desarrollo en Solana