El Pequeño Cambio Que Generó Un Gran Impacto

Introducción

En este artículo te comparto una experiencia que me enseño que muchas veces los pequeños detalles son suficiente para resolver ese gran problema que tiene un sistema en producción, o para mejorar el performance de un proceso que por algún motivo desconocido está demorando bastante más de lo esperado.

Contexto

Hace algún tiempo tuve que desarrollar una tarea que parecía bastante compleja, al menos para lograr una solución que verdaderamente cumpliera lo esperado, y era básicamente disminuir los tiempos de respuesta en uno de los flujos principales de nuestra aplicación. De forma general y para darte un poco de contexto, el flujo te lo muestro a continuación:

A grandes rasgos el flujo a nivel de backend consistía en lo siguiente:

• El api de producto pedía al proveedor la información de los itinerarios correspondientes
• El proveedor, que es un API de terceros, procesa la información y devuelve al api de productos los itinerarios correspondientes
• Luego el api de producto hace una petición al api de reglas, este API hace cierto procesamiento para determinar que regla aplica a cada itinerario
• Por último, el api de regla devuelve al api de producto la regla que debe aplicarse a cada itinerario

No es necesario que entiendas que es una regla o la lógica como tal debajo de cada uno de estos procesos, esto es solo para que entiendas a modo general los distintos componentes envueltos en este flujo.

Lo primero que hice fue loguear el tiempo que demoraba cada proceso, siempre bajo la premisa que el tiempo que demore el proveedor no es algo que podía controlar, por lo tanto debía enfocarme en mejorar el flujo en el api de producto o en el api de reglas. Aquí vino la primera sorpresa, este proceso estaba demorando en los casos críticos hasta 90 segundos, cuando el proveedor demoraba alrededor de 15 segundos en responder los itinerarios. O sea, estábamos añadiendo una demora de 75 segundos de nuestro lado, algo que definitivamente debía poder optimizarse.

Lo primero que hice fue mediante logs, determinar cuanto tiempo tomaba cada proceso, aquí, para mi sorpresa, me di cuenta que había una parte del flujo, la de aplicar las reglas de precio a cada itinerario, que tomaba más de la mitad del tiempo total, o sea, aquí estaba el cuello de botella. Ahora veamos en que consistía esta parte del flujo

func (c *CommercialPoliciesClient) applyCommercialPolicies(request *Request, agencyCommercialPolicies map[string]common.CommercialPolicy, resellerCommercialPolicies map[string]common.CommercialPolicy) ([]common.Itinerary, error) {

    //Inicializaciones

	for index := range request.Itineraries {

		wp.Submit(func() {
            // Este código se ejecuta en paralelo para cada itinerario

			defer mutex.Unlock()

			mutex.Lock()

			agencyPolicy, ok := getAgencyCommercialPolicy(request.Itineraries[i].ID)
			if !ok {
				logrus.Warnf("ignore itinerary[%s] because have not agency commercial policy", request.Itineraries[i].ID)

				return
			}

			resellerPolicy, ok := getResellerCommercialPolicy(request.Itineraries[i].ID)
			if !ok {
				logrus.Warnf("ignore itinerary[%s] because have not reseller commercial policy", request.Itineraries[i].ID)

				return
			}

			c.applyCommercialPolicy(request.SearchRequest, currencyRatiosCache, c.applicable, resellerPolicy, &request.Itineraries[i])
			c.applyCommercialPolicy(request.SearchRequest, currencyRatiosCache, c.applicable, agencyPolicy, &request.Itineraries[i])

			result = append(result, request.Itineraries[i])
		})
	}

	wp.StopWait()

	return result, nil
}

Digamos que este código era la causa principal de la demora en el flujo y esto se demuestra a continuación:

El tiempo total es un poco mayor a la suma de los otros tiempos debido al tiempo de transmisión de datos entre cada API

Como podemos ver, para este caso específico, se estaban procesando 890 itinerarios, y el proceso de aplicar las reglas demoraba alrededor de 37 segundos, lo que representaba más del 75% del tiempo total del flujo.

Aquí comenzaron a llamarme la atención varias cosas:

1. El proceso de aplicar las reglas se estaba ejecutando en paralelo, por lo tanto no era un problema de que el proceso fuera secuencial, sino que había algo que estaba causando la demora para cada iteración.
2. El lenguaje de programación que estábamos usando era Go, un lenguaje que se caracteriza por su eficiencia y por el uso de goroutines para manejar concurrencia, por lo tanto no debería haber un problema de performance en este caso.
3. Cada iteración consistía básicamente en la manipulación de los datos, o sea, no había procesos asíncronos o llamadas a APIs externas que pudieran estar causando la demora.

La sorpresa

Empecé a darme cuenta que cuando todos los itinerarios tenían una regla asiganada, el proceso era extremadamente rápido, pero cuando había itinerarios que no tenían una regla asignada, el proceso se demoraba mucho más. Esto era raro debido a que si un itineario no tenía regla asignada, simplemente se ignoraba y se continuaba con el siguiente itinerario. Luego de hacer un análisis más produndo, me di cuenta que cuando un itinerario no tenía regla asignada, se logueaba un mensaje de advertencia, y este mensaje era el que estaba causando la demora.

Esto se debe a que a pesar de que el procesamiento se hace en paralelo, el logueo de mensajes no es concurrente debido a que se usa el mismo buffer a nivel de sistema operativo, y cuando se intenta escribir en el buffer desde múltiples goroutines al mismo tiempo, se produce un bloqueo que causa una demora significativa. En este caso, cada vez que se intentaba loguear un mensaje de advertencia, se producía un bloqueo que afectaba el rendimiento del proceso.

Honestamente nunca pensé que esta fuera la causa de la demora, y para ser honesto, cuando eliminé los logs y vi la diferencia de tiempo, no lo quería creer. Incluso cerré y abrí el proyecto varias veces 😂 porque no me lo creía. En la próxima tabla te muestro los tiempos luego de eliminar los logs:

Como puedes ver, el proceso de aplicar las reglas pasó de demorar 36.86 segundos a solo 0.006 segundos, o sea, una mejora de más del 99%. Esto es algo que definitivamente no me esperaba, y que me enseñó una lección muy importante sobre la importancia de los pequeños detalles en el desarrollo de software.

Prueba de concepto

Un poco para que puedas verificar lo que te he mostrado en este artículo, te dejo un pequeño ejemplo de código que puedes ejecutar en tu máquina para ver la diferencia de tiempo al loguear mensajes desde múltiples goroutines:

func main() {
	const iterations = 1000000

	// First cycle: just increment counter
	start1 := time.Now()
	counter1 := 0
	for i := 0; i < iterations; i++ {
		counter1++
	}

	elapsed1 := time.Since(start1)

	// Second cycle: increment counter and log every 100 iterations
	start2 := time.Now()
	counter2 := 0
	var wg sync.WaitGroup
	for i := 0; i < iterations; i++ {
		wg.Add(1)
		go func(i int) {
			defer wg.Done()
			counter2++
			if i%100 == 0 {
				fmt.Printf("Second cycle at iteration: %d\n", i)
			}
		}(i)
	}
	wg.Wait()
	elapsed2 := time.Since(start2)

	fmt.Printf("First cycle took: %v\n", elapsed1)
	fmt.Printf("Second cycle took: %v\n", elapsed2)
}

Si ejecutas este código, te darás cuenta que a pesar de que el segundo ciclo ejecuta cada iteración en paralelo, toma una cantidad de tiempo significativamente mayor debido al logueo de mensajes.

Hasta la próxima

Esto es todo por este artículo, espero que te haya servido ya que al menos para mi, esto fue una gran experiencia que me demostró que a veces el detalle más insignificante puede ser la causa de un gran problema en un sistema. Si tienes algún comentario, no dudes en dejarlo en la sección de comentarios. ¡Hasta la próxima!