loading...

the #1 Ruby benchmarking tool you didn't know you need

andy4thehuynh profile image Andy Huynh Updated on ・1 min read

Attention web developers working with lots of data - below are first class problems to consider:

  • slow database queries
  • page time outs

When customer support barks at you to resolve a 500 error, what do you do? Initial instincts suggest the two problems are related. Especially in applications with lots of user data.

Here's step #1.. your only dance move for Ruby benchmarking: Benchmark#realtime

Here is an example from my day job at Kajabi: CX gets assigned with a customer support ticket. They log into Kajabi's super admin dashboard to search for the customer (a User). The page returns a 500 error and it doesn't render.

page timeouts

You want to know how long it's taking to retrieve the user. That's the first step to ensure you're going down the right rabbithole.

$ Benchmark.realtime { User.search("Sharon Jackson") }
=> 22.409309996990487

The result is the elapsed time. Searching a user cost 22 seconds! yikes.

Heroku has a threshold of 30 seconds before it fails to load a page. Postgres caches our first request so that subsequent requests read from a cached result. Heroku does this to ensure quicker response times.

I went and recorded how long it took before the page timed out. Approximately 22 seconds. Down the rabbithole you go from there.

Posted on May 9 by:

andy4thehuynh profile

Andy Huynh

@andy4thehuynh

πŸ‘¨πŸ»β€πŸ’» software developer πŸ’™ kajabi.com | homecook β€’ telecaster β€’ minimalist | #ruby #rails

Discussion

markdown guide
 

I went and recorded how long it took before the page timed out. Approximately 22 seconds. Down the rabbithole you go from there.

Generic tip from my experience:

  1. get the SQL query executed by User.search()
  2. run EXPLAIN ANALYZE {SQL QUERY} and see what's going on (you can use tools like explain.depesz.com/ to make it more readable)
  3. check what's the situation with indices

IIRC .search comes from Ransack which likely uses LIKE or ILIKE which can be a very expensive operation (22 seconds is definitely too much) with a non trivial amount of rows to scan. LIKE operators don't use indexes which means the DB has to sequentially scan each row to provide an answer:

PracticalDeveloper_development=# SET enable_seqscan = false;
SET
Time: 0.222 ms
PracticalDeveloper_development=# explain analyze select * from users where username = 'rhymes';
β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”
β”‚                                                            QUERY PLAN                                                            β”‚
β”œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€
β”‚ Index Scan using index_users_on_username on users  (cost=0.14..8.15 rows=1 width=1355) (actual time=0.192..0.197 rows=1 loops=1) β”‚
β”‚   Index Cond: ((username)::text = 'rhymes'::text)                                                                                β”‚
β”‚ Planning Time: 0.167 ms                                                                                                          β”‚
β”‚ Execution Time: 0.273 ms                                                                                                         β”‚
β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜
(4 rows)

Time: 1.323 ms
PracticalDeveloper_development=# explain analyze select * from users where username like 'rhy%';
β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”
β”‚                                                      QUERY PLAN                                                      β”‚
β”œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€
β”‚ Seq Scan on users  (cost=10000000000.00..10000000005.14 rows=1 width=1355) (actual time=0.042..0.043 rows=1 loops=1) β”‚
β”‚   Filter: ((username)::text ~~ 'rhy%'::text)                                                                         β”‚
β”‚   Rows Removed by Filter: 10                                                                                         β”‚
β”‚ Planning Time: 0.868 ms                                                                                              β”‚
β”‚ Execution Time: 3.412 ms                                                                                             β”‚
β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜
(5 rows)

Time: 5.460 ms

You could use trigrams, with the extension pg_tgrm to enable index scanning on LIKE operators:

PracticalDeveloper_development=# CREATE EXTENSION pg_trgm;
CREATE EXTENSION
Time: 215.856 ms
PracticalDeveloper_development=# CREATE INDEX trgm_idx ON users USING GIST (username gist_trgm_ops);
CREATE INDEX
Time: 29.489 ms
PracticalDeveloper_development=# explain analyze select * from users where username like 'rhy%';
β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”
β”‚                                                    QUERY PLAN                                                     β”‚
β”œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€
β”‚ Index Scan using trgm_idx on users  (cost=0.13..8.15 rows=1 width=1355) (actual time=0.064..0.065 rows=1 loops=1) β”‚
β”‚   Index Cond: ((username)::text ~~ 'rhy%'::text)                                                                  β”‚
β”‚ Planning Time: 1.017 ms                                                                                           β”‚
β”‚ Execution Time: 0.116 ms                                                                                          β”‚
β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜
(4 rows)

Time: 1.934 ms

Note the difference in execution time ;-)

This is a great answer:

FTS does not support LIKE

The previously accepted answer was incorrect. Full Text Search with its full text indexes is not for the LIKE operator at all, it has its own operators and doesn't work for arbitrary strings. It operates on words based on dictionaries and stemming. It does support…

and here you can find more details on pg_tgrm: postgresql.org/docs/12/pgtrgm.html

Hope this helps :-)

 

I'm writing on a yellow stickie as a reminder.

I forget EXPLAIN exists time and time again. Thank you!