Home / MAD1 / Week 7

Week 7 · Backend systems: indexing, search, caching and logging

The one-minute story

By the end of this week you can:

• predict the output of Python logging programs for any level and format;
• debug a Flask app with debug mode, pdb, the Flask shell and tracebacks;
• create an index, read EXPLAIN QUERY PLAN, and say when an index helps and when it hurts;
• build a full-text search with SQLite FTS5 and keep it in sync with triggers;
• explain caching (client vs server, TTL, keys, invalidation, Cache-Control, ETag) and use Flask-Caching;
• calculate latency, throughput, bandwidth, data volume and requests per second;
• explain scaling, load balancers, stateless servers, batch jobs, N+1 queries and pagination.

Words you need

Idea 1: Logging (the app's diary)

print() is fine on day one. A real app needs levels, timestamps, files, and the ability to switch noise on and off without editing every line. That is the logging module.

import logging
logging.basicConfig(level=logging.INFO,
                    format='%(levelname)s:%(name)s:%(message)s')
log = logging.getLogger("shop")
log.debug("hidden")             # 10 < 20, suppressed
log.info("hello %s", "ravi")    # shown
log.warning("low stock")
log.error("fail")
log.critical("down")

Output (checked by running it):

INFO:shop:hello ravi
WARNING:shop:low stock
ERROR:shop:fail
CRITICAL:shop:down

Handlers, formatters, loggers. A logger (named, e.g. "shop") creates records. A handler sends them somewhere (StreamHandler = console, FileHandler("app.log")). A formatter turns the record into text using fields like %(asctime)s, %(levelname)s, %(message)s, %(name)s. Each handler can have its own level, so you can print everything to the screen but save only errors to a file:

fh = logging.FileHandler("app.log")
fh.setLevel(logging.ERROR)
fh.setFormatter(logging.Formatter("%(asctime)s %(levelname)s %(message)s"))
log.addHandler(fh)
log.warning("seen on console only")
log.error("seen on console and in app.log")

basicConfig() is a one-line setup of the root logger. Other details that are asked:

• logging.exception("msg") is error plus the full traceback; use it inside except.
• Use lazy formatting: log.info("user %s", name), not an f-string, so the string is built only if the level is on.
• basicConfig does nothing if the root logger already has handlers; call it once, early.
• Flask's logger is app.logger (named after your app). It logs unhandled exceptions as ERROR with a traceback and returns 500 to the browser. In debug mode Flask also shows werkzeug's request lines.

@app.route("/")
def home():
    app.logger.info("visited home")
    return "ok"

import logging, sys
logging.basicConfig(level=logging.INFO,
                    format='%(levelname)s - %(message)s')
num1, num2 = int(sys.argv[1]), int(sys.argv[2])
logging.info("This operation checks factors")
if num1 % num2 == 0:
    logging.debug(f"{num2} is a factor of {num1}")
else:
    logging.warning(f"{num2} is not the factor of {num1}")

Idea 2: Debugging

Debug mode. app.run(debug=True) (or flask --app app run --debug) does two things: it auto-reloads when you save a file, and it shows an interactive error page with the traceback in the browser. Never use it in production, because it lets anyone who sees the page run code on your server.

Reading a traceback. Read it from the bottom: the last line is the exception type and message; the line above shows the exact line of your code that failed; the lines above show who called whom.

Traceback (most recent call last):
  File "app.py", line 11, in b
    return 1/0
ZeroDivisionError: division by zero

pdb, the Python debugger. Put breakpoint() (or import pdb; pdb.set_trace()) where you want to stop. Execution pauses with a (Pdb) prompt:

Flask shell. flask --app app shell opens a Python prompt with the app context already pushed, so db, models and queries work right away. It is the fastest way to test a query or insert test data.

flask --app app shell
>>> User.query.count()

Idea 3: Database indexing

Without help, SELECT * FROM student WHERE city='c7' makes SQLite read every row (a full table scan, cost proportional to n). An index is a separate sorted structure, like the index at the back of a book: it maps a column value to the rows that hold it.

B-tree intuition. Real indexes are B-trees: a short, wide tree whose nodes hold many sorted keys. To find a value you go from the root down a few levels, choosing the right branch at each node. For a million rows a binary search needs about 20 comparisons; a B-tree with 100 keys per node needs only about 3 levels. Cost grows with the logarithm of the table size, not the size itself.

import sqlite3
c = sqlite3.connect(":memory:")
c.execute("create table student(id integer primary key, name text, city text, marks int)")
c.executemany("insert into student(name,city,marks) values(?,?,?)",
              [("s%d" % i, "c%d" % (i % 50), i % 100) for i in range(10000)])
q = "select * from student where city='c7'"
print(c.execute("explain query plan " + q).fetchall())
c.execute("create index idx_city on student(city)")
print(c.execute("explain query plan " + q).fetchall())

Real output (the middle numbers differ by version):

[(2, 0, 216, 'SCAN student')]
[(3, 0, 62, 'SEARCH student USING INDEX idx_city (city=?)')]

SCAN = reads all rows. SEARCH ... USING INDEX = uses the index. EXPLAIN QUERY PLAN shows what SQLite plans to do without running the query.

In Flask-SQLAlchemy: city = db.Column(db.String, index=True) creates the index with the table. Foreign key columns used in joins are good candidates.

Idea 4: Full-text search with SQLite FTS5

WHERE body LIKE '%flask%' scans everything and cannot rank results. FTS5 is an SQLite extension that builds an inverted index (word -> list of rows containing it). You create a virtual table: it looks like a table but is stored in special search structures.

c.execute("create virtual table notes using fts5(title, body)")
c.execute("insert into notes values('Flask intro','Flask is a micro framework'),"
          "('Jinja','Templates for Flask apps'),('SQL','Indexes make queries fast')")
print(c.execute("select title from notes where notes match 'flask'").fetchall())
print(c.execute("select title from notes where notes match 'micro OR index*'").fetchall())

[('Flask intro',), ('Jinja',)]
[('Flask intro',), ('SQL',)]

• MATCH searches words; 'micro OR index*' uses OR and the prefix star index* (matches indexes). Also AND, NOT and quoted phrases '"micro framework"'.
• Matching is by whole words (the default tokenizer does no stemming): cache does not match caching; use cache*.
• Order by relevance with ORDER BY rank; highlight with snippet(...) or highlight(...).

Keeping it in sync. If your real data lives in a normal table post, make the FTS table an external-content table and add triggers (automatic actions that run after insert, update, delete) so the search index never goes stale:

create table post(id integer primary key, title text, body text);
create virtual table post_fts using fts5(title, body, content='post', content_rowid='id');
create trigger post_ai after insert on post begin
  insert into post_fts(rowid,title,body) values (new.id,new.title,new.body);
end;
create trigger post_ad after delete on post begin
  insert into post_fts(post_fts,rowid,title,body) values('delete',old.id,old.title,old.body);
end;
create trigger post_au after update on post begin
  insert into post_fts(post_fts,rowid,title,body) values('delete',old.id,old.title,old.body);
  insert into post_fts(rowid,title,body) values (new.id,new.title,new.body);
end;

Search and join back to the real rows: select p.id,p.title from post_fts f join post p on p.id=f.rowid where post_fts match 'cache*'. We tested all three triggers: after an update the new words match, after a delete the row disappears from results.

Idea 5: Caching

A cache stores the result of expensive work (a database query, a rendered page, an API call) so the next identical request is answered instantly. Why: lower latency for the user, less load on the server and database, lower cost.

Server-side with Flask-Caching. (Install flask-caching.)

from flask_caching import Cache
cache = Cache(app, config={"CACHE_TYPE": "SimpleCache", "CACHE_DEFAULT_TIMEOUT": 60})

@app.route("/slow")
@cache.cached(timeout=30)          # whole response cached for 30 s
def slow():
    ...

@cache.memoize(timeout=30)         # cache by function arguments
def square(x): ...

We ran this: two calls of /slow ran the function once (the second came from the cache). square(4) twice ran once, but square(5) would compute again, because the cache key includes the arguments. A cache key is the label under which the result is stored: for @cache.cached it is the request path, for memoize it is the function name plus arguments.

Client-side caching with HTTP headers.

• Cache-Control: public, max-age=60 - any cache may reuse this response for 60 s without asking. private = only the user's browser. no-store = never keep it.
• ETag - a fingerprint of the response ("v1"). Next time the browser sends If-None-Match: "v1". If unchanged the server replies 304 Not Modified with no body: the browser reuses its copy and saves bandwidth. If changed: 200 with the new body.

@app.route("/data")
def data():
    resp = make_response('{"v": 1}')
    resp.set_etag("v1")
    resp.headers["Cache-Control"] = "public, max-age=60"
    return resp.make_conditional(request)

Tested: first request 200 with ETag: "v1"; second request with If-None-Match: "v1" gave 304 and an empty body.

REST APIs and caching. Only safe, idempotent reads (GET) are meant to be cached. POST, PUT, DELETE change data and are not cached by default. A paper asked which statements about REST caching were false; the false ones were: "caching degrades service and increases server load", "browsers treat all GET and POST requests as cacheable by default", and "caching optimises the network by increasing latency". Caching reduces latency and load; only GET is cacheable by default.

Idea 6: Performance vocabulary and arithmetic

Latency is "how long until the first byte" (delay). Throughput is "how much per second" (rate). Bandwidth is the maximum rate a link or memory can carry. A highway analogy: latency is the travel time of one car; bandwidth is the number of lanes.

Memory hierarchy (fast and small at the top, slow and large at the bottom):

So "highest latency" = HDD, "lowest density" = registers, "lowest throughput" = HDD. For small, hot data wanting very low latency (such as frequently used records), the answer in the papers is SRAM-like cache memory.

The arithmetic. Convert units first: 1 byte = 8 bits; use the question's own definition (usually 1 KB = 1000 B, 1 MB = 1000 KB).

Other quick formulas: disk worst-case rotational latency = one full rotation = 60000 / RPM milliseconds (6000 RPM gives 10 ms, 5000 RPM gives 12 ms; the average is half). HDD throughput = data per revolution x revolutions per second: to match an SSD of 180 MB/s with 4.8 Mbit (0.6 MB) per revolution you need 300 rev/s = 18000 RPM.

Idea 7: Scaling, stateless servers, background jobs

• Scale up (vertical): a bigger machine (more RAM, CPU). Simple, but has a ceiling and one point of failure.
• Scale out (horizontal): more machines behind a load balancer, which spreads requests (round robin, least connections). Practically unlimited, and one machine failing does not stop the site.
• Stateless servers make scale-out easy: if user data lives in the database or a shared store (Redis) and not in one server's memory, any server can answer any request. This is why a login can be carried by a token or a shared session store instead of a local variable.
• Redundancy and replication: keeping copies (extra servers, database replicas) for availability and fault tolerance. A paper had two statements, "redundancy improves performance and reduces load" and "replication ensures data is not lost", and marked both false. The official wording favours: redundancy is for reliability, not speed, and "ensures" is too strong. Check your course notes for the exact phrasing.
• ACID vs BASE: ACID (atomic, consistent, isolated, durable) suits financial transactions; BASE (basically available, soft state, eventually consistent) suits social media feeds. In the paper: scale up = increasing RAM, scale out = adding physical servers.

Session memory is also a scaling calculation: 1.5 million sessions x 4 KB = 6,000,000,000 bytes = 6 GB of RAM (a paper asked this for a Redis session store).

Background (batch) jobs. Work that is slow and does not need an instant answer (emailing reports, resizing images, nightly exports) should not block the web request. The request puts a job on a queue and returns at once; a separate worker takes jobs from the queue. Cron runs a task on a schedule ("every night at 2"). The tool for this in Flask is Celery, which you meet in MAD2; here you only need the idea.

Idea 8: N+1 queries and pagination

N+1 problem. One query fetches N authors, then touching author.books fires one more query per author: N+1 queries. We counted queries with 5 authors and 3 books each:

for a in Author.query.all():          # 1 query
    len(a.books)                      # +5 lazy queries  -> 6 total
for a in Author.query.options(selectinload(Author.books)).all():   # 2 queries
    len(a.books)
for a in Author.query.options(joinedload(Author.books)).all():     # 1 query (JOIN)
    len(a.books)

Measured: 6, 2 and 1 queries. Fix: eager loading (selectinload, joinedload) or a single JOIN. Add an index on foreign keys.

Pagination. Never return a million rows. Return a page at a time with LIMIT and OFFSET (or db.paginate):

p = db.paginate(db.select(Book).order_by(Book.id), page=2, per_page=4)
# p.items = [b11, b12, b20, b21]; p.page=2, p.pages=4, p.total=15, p.has_next, p.has_prev

Always add ORDER BY so pages are stable. API shape: GET /books?page=2&per_page=4.

Your turn

Exam radar

Quick quiz

Viva: say it out loud

Recap

Practise with real exam questions

These come straight from past papers (with the real figures and the official answer key). Open 60 real questions on this week   All Quiz 2 papers