Seeing a big disparity between the actual query execution time and how long it takes node-postgres to produce results

[lilouartz]

SELECT sp3.*
FROM supplement_product sp1
INNER JOIN iherb_product ip1 ON ip1.id = sp1.iherb_product_id CROSS JOIN LATERAL unnest(
  ip1.related_products) AS related_product_id
INNER JOIN iherb_product ip2 ON ip2.iherb_product_foreign_id = related_product_id
INNER JOIN supplement_product sp2 ON sp2.iherb_product_id = ip2.id
INNER JOIN (
SELECT *
FROM resolved_supplement_product) sp3 ON sp3.id = sp2.id
WHERE sp3."bestOffer" IS NOT NULL AND (sp3."labelImage" IS NOT NULL OR sp3."triptychImage" IS NOT NULL) AND
   sp3."aggregateRating" IS NOT NULL AND sp1.id = 3254
LIMIT 6

Let's use this as an example.

I have reporting enabled for this query in Postgres. The average reported execution time is sub 2 milliseconds.

Meanwhile, I've also instrumented code to track how long it takes to run this query in the codebase, i.e.

console.time('query');
await client.query(`
    SELECT sp3.*
    FROM supplement_product sp1
    INNER JOIN iherb_product ip1 ON ip1.id = sp1.iherb_product_id CROSS JOIN LATERAL unnest(
      ip1.related_products) AS related_product_id
    INNER JOIN iherb_product ip2 ON ip2.iherb_product_foreign_id = related_product_id
    INNER JOIN supplement_product sp2 ON sp2.iherb_product_id = ip2.id
    INNER JOIN (
    SELECT *
    FROM resolved_supplement_product) sp3 ON sp3.id = sp2.id
    WHERE sp3."bestOffer" IS NOT NULL AND (sp3."labelImage" IS NOT NULL OR sp3."triptychImage" IS NOT NULL) AND
      sp3."aggregateRating" IS NOT NULL AND sp1.id = 3254
    LIMIT 6
`)
console.timeEnd('query');

The latter reports an average of ~40 milliseconds.

I've ruled out things like...

• the latency to the server (the latency to the server is sub 1 millisecond)
• resource constraints (CPU utilization is under 5%)
• appears to be specific to the query, e.g. a query such as SELECT 1 returns results sub 4 milliseconds.

Running out of ideas and would appreciate any help in trying to understand where the massive overhead is coming from. Is it just the efficiency of the node-postgres implementation?

Here is an example of data row from that query (many of them are JSON):

[
	{
		"id": 3055,
		"slug": "vitamin-b1",
		"name": "Vitamin B1",
		"descriptionMarkdown": "* **Boosts Energy**: Contains **thiamin 300 mg**, which plays a crucial role in converting food into energy, helping to reduce fatigue and increase stamina throughout the day.\n* **Supports Nervous System**: Thiamin is essential for the proper functioning of the nervous system, contributing to better nerve health and cognitive function.\n* **Gluten-Free**: Perfect for individuals with gluten sensitivities, ensuring safe and effective supplementation without adverse reactions.\n* **Vegetarian-Friendly**: Made with vegetarian ingredients, this tablet aligns with vegetarian lifestyles while still delivering essential nutrients.\n* **High Potency Formula**: With 300 mg of thiamin per tablet, you receive a potent dose in each serving, ensuring you meet your daily vitamin B1 needs.\n* **Quality You Can Trust**: NaturesPlus is committed to using high-quality ingredients and rigorous manufacturing processes, giving you a supplement you can rely on for your health and well-being.\n* **Convenient Tablet Form**: Easy-to-swallow tablets that fit seamlessly into your daily routine, making it simple to maintain your health regimen with minimal effort.",
		"updated_at": "2024-08-17 11:44:39.728857+00",
		"upcCode": "097467016057",
		"brand_id": 1742,
		"healthOutcomes": [
		],
		"attributes": [
			{
				"id": 3,
				"name": "Gluten Free",
				"slug": "gluten-free",
				"description": "Free from gluten and gluten-containing ingredients."
			},
			{
				"id": 11,
				"name": "Vegetarian",
				"slug": "vegetarian",
				"description": "Suitable for vegetarians, containing no meat or fish."
			}
		],
		"certifications": [
		],
		"labelImage": {
			"width": 2740,
			"height": 1046,
			"placeholder": "data:image/avif;base64,AAAAHGZ0eXBhdmlmAAAAAGF2aWZtaWYxbWlhZgAAAOptZXRhAAAAAAAAACFoZGxyAAAAAAAAAABwaWN0AAAAAAAAAAAAAAAAAAAAAA5waXRtAAAAAAABAAAAImlsb2MAAAAAREAAAQABAAAAAAEOAAEAAAAAAAAA9AAAACNpaW5mAAAAAAABAAAAFWluZmUCAAAAAAEAAGF2MDEAAAAAamlwcnAAAABLaXBjbwAAABNjb2xybmNseAABAA0ABoAAAAAMYXYxQ4EgAgAAAAAUaXNwZQAAAAAAAABkAAAAJgAAABBwaXhpAAAAAAMICAgAAAAXaXBtYQAAAAAAAAABAAEEAYIDBAAAAPxtZGF0EgAKCTgZccrCAhoNIDLkARQADjkKgoDLPy4JcgdGDFk+Zf1bx7s6RJ9/RpMTJzr+SjIMm8THoNt1ff+GKcV+4lGcA0VBNuWGbtNS3QEN/zneW1SK4BVvunjS5RNs9MrdIvPTgVuKApP4YQCfqnh74hR+TXoV/rkbjcUe8TXM3vrGnps4GKpMIbYE9yrIsA0l7Ud24sIei/HqaAlS8kOUU0aPr1bUJ2ChW9jca7T3ubb6fvL5bayxmfuIwauW1kty/X6o012cSA6u+OzBgAIVPgjc5WThYfmuI1wCbulq+xqYAuuCeumFUwaagTnFJkNApXlBsA=="
		},
		"triptychImage": {
			"width": 2714,
			"height": 1605,
			"placeholder": "data:image/avif;base64,AAAAHGZ0eXBhdmlmAAAAAGF2aWZtaWYxbWlhZgAAAOptZXRhAAAAAAAAACFoZGxyAAAAAAAAAABwaWN0AAAAAAAAAAAAAAAAAAAAAA5waXRtAAAAAAABAAAAImlsb2MAAAAAREAAAQABAAAAAAEOAAEAAAAAAAABFwAAACNpaW5mAAAAAAABAAAAFWluZmUCAAAAAAEAAGF2MDEAAAAAamlwcnAAAABLaXBjbwAAABNjb2xybmNseAABAA0ABoAAAAAMYXYxQ4EgAgAAAAAUaXNwZQAAAAAAAABkAAAAOwAAABBwaXhpAAAAAAMICAgAAAAXaXBtYQAAAAAAAAABAAEEAYIDBAAAAR9tZGF0EgAKCTgZcfTCAhoNIDKHAhQACyyyAoDXDGSag0Me22SmRIhd9la1qnQTy3frdyXRYO6ohv2jz8YBSWdKPzE7HjE7chYzsaF0jVPss4dLD5J6TWci/fFdL2/uMubEhBEqK615FHOgvK82s/6xJxwuL6vFFbmTD9KOMSI7cM6KMPDMdwMO3MsAIWtc1b6YIGeEGRv5v8g8GtaCADY6wyZrh9GPnjGMvJYGa6ESCptfTNb/UgeAzMhJUgEX2Sogwr35+Njzc7NncVp2zsJA7r4cppTxt77QwZClT53wn8s9FQKiMaggmX5WoNnAAu6HIm9cTxGjw9nR/Vh3CtrvZRyxfcabHbphhDUU1VNtXCUgpEjB3WqFptV8"
		},
		"pillType": {
			"id": 1,
			"name": "Tablet"
		},
		"pillCount": 90,
		"mainIngredientMeasurement": {
			"unit": "mg",
			"amount": 300
		},
		"flavor": null,
		"brand": {
			"id": 1742,
			"name": "NaturesPlus",
			"slug": "naturesplus"
		},
		"servingInformation": {
			"servingSize": 1,
			"servingsPerContainer": 90
		},
		"ingredientsPerServing": [
			{
				"id": 267538,
				"lipid": null,
				"enzyme": null,
				"details": "thiamin",
				"mineral": null,
				"protein": null,
				"vitamin": {
					"id": 1,
					"name": "Vitamin B1",
					"slug": "vitamin-b1"
				},
				"lessThan": false,
				"aminoAcid": null,
				"probiotic": null,
				"measurement": {
					"unit": {
						"abbreviation": "mg"
					},
					"amount": 300,
					"amountMcg": 300000.0,
					"totalAmountMcg": 27000000.0
				},
				"herbalExtract": null,
				"subIngredients": [
					{
						"id": 267539,
						"lipid": null,
						"enzyme": null,
						"details": "vitamin B1",
						"mineral": null,
						"protein": null,
						"vitamin": {
							"id": 1,
							"name": "Vitamin B1",
							"slug": "vitamin-b1"
						},
						"lessThan": false,
						"aminoAcid": null,
						"probiotic": null,
						"measurement": null,
						"herbalExtract": null
					}
				]
			}
		],
		"excipientIngredients": [
			{
				"id": 267540,
				"lipid": null,
				"enzyme": null,
				"details": "hydroxypropyl methylcellulose",
				"mineral": null,
				"protein": null,
				"vitamin": null,
				"lessThan": false,
				"aminoAcid": null,
				"probiotic": null,
				"measurement": null,
				"herbalExtract": null,
				"subIngredients": [
				]
			},
			{
				"id": 267541,
				"lipid": null,
				"enzyme": null,
				"details": "stearic acid",
				"mineral": null,
				"protein": null,
				"vitamin": null,
				"lessThan": false,
				"aminoAcid": null,
				"probiotic": null,
				"measurement": null,
				"herbalExtract": null,
				"subIngredients": [
				]
			},
			{
				"id": 267542,
				"lipid": null,
				"enzyme": null,
				"details": "magnesium stearate",
				"mineral": null,
				"protein": null,
				"vitamin": null,
				"lessThan": false,
				"aminoAcid": null,
				"probiotic": null,
				"measurement": null,
				"herbalExtract": null,
				"subIngredients": [
				]
			},
			{
				"id": 267543,
				"lipid": null,
				"enzyme": null,
				"details": "rice bran",
				"mineral": null,
				"protein": null,
				"vitamin": null,
				"lessThan": false,
				"aminoAcid": null,
				"probiotic": null,
				"measurement": null,
				"herbalExtract": null,
				"subIngredients": [
				]
			},
			{
				"id": 267544,
				"lipid": null,
				"enzyme": null,
				"details": "pharmaceutical glaze",
				"mineral": null,
				"protein": null,
				"vitamin": null,
				"lessThan": false,
				"aminoAcid": null,
				"probiotic": null,
				"measurement": null,
				"herbalExtract": null,
				"subIngredients": [
				]
			}
		],
		"absentIngredients": [
			{
				"id": 267545,
				"lipid": null,
				"enzyme": null,
				"details": "artificial colors",
				"mineral": null,
				"protein": null,
				"vitamin": null,
				"lessThan": false,
				"aminoAcid": null,
				"probiotic": null,
				"measurement": null,
				"herbalExtract": null,
				"subIngredients": [
				]
			},
			{
				"id": 267546,
				"lipid": null,
				"enzyme": null,
				"details": "artificial preservatives",
				"mineral": null,
				"protein": null,
				"vitamin": null,
				"lessThan": false,
				"aminoAcid": null,
				"probiotic": null,
				"measurement": null,
				"herbalExtract": null,
				"subIngredients": [
				]
			}
		],
		"amazonProduct": null,
		"iherbProduct": {
			"id": 22040,
			"oneTimePurchasePrice": {
				"amount": 16.96
			}
		},
		"vitacostProduct": null,
		"vitaminshoppeProduct": null,
		"bestOffer": {
			"price": 16.96,
			"store": "iherb"
		},
		"availability": "OUT_OF_STOCK",
		"aggregateRating": {
			"count": 479,
			"value": 4.8
		},
		"discoverable": true
	}
]

[lilouartz]

I just did more testing and realized that the response time depends on the number of rows returned, i.e. It does look like the overhead comes from the protocol-level of handling the data.