Request Lifecycle Deep Dive

Scenario

User clicks search in RAGFlow UI, sending this HTTP request:

POST /api/v2/search HTTP/1.1
Content-Type: application/json

{
  "query": "how to train a model",
  "knowledge_base_id": "kb_12345",
  "top_k": 10
}

Timeline: 0ms - 150ms

t=0ms     t=5ms    t=10ms   t=50ms     t=100ms  t=150ms
|---------|--------|--------|----------|---------|----------|
TLS       Gin      Handler  Search     DB       Response
Decrypt   Route    Validate Service    Vector   Sent
                   Unmarshal         Search

Phase 1: Network & Decryption (0-1ms)

Step 1: TLS Handshake (already done, reusing connection)

Browser has persistent HTTPS connection. Request arrives encrypted.

Step 2: TLS Decryption

Time: 0.2ms
Nginx proxy decrypts TLS (hardware AES-NI)
Raw HTTP bytes available to Go process

Phase 2: Gin Router (1-2ms)

Step 3: Gin Receives Request

Time: 0.1ms (negligible)
Gin sees: POST /api/v2/search
Radix tree lookup finds SearchHandler

Gin Handler Chain

1. CORSMiddleware (allowed origins check) - 0.05ms
2. LoggingMiddleware (request ID, timing) - 0.05ms
3. JWTMiddleware (verify token signature) - 0.3ms
   - Extract "Bearer {token}" from header
   - Verify RS256 signature (cached public key)
   - Extract user_id, tenant_id
4. TenantMiddleware (inject tenant context) - 0.1ms
5. SearchHandler.Search() called

Total Phase 2: 0.5ms

Phase 3: Handler Validation (2-3ms)

Step 4: HTTP Request Unmarshaling

Time: 0.3ms
gin.Context.ShouldBindJSON(&req) unmarshals POST body

Go struct:
type SearchRequest struct {
    Query            string `json:"query" binding:"required,max=500"`
    KnowledgeBaseID  string `json:"knowledge_base_id" binding:"required"`
    TopK             int    `json:"top_k" binding:"gte=1,lte=100"`
}

Step 5: Input Validation

Time: 0.2ms
Check binding rules:
- query not empty and len(query) <= 500?  Check
- kb_id not empty?  Check
- top_k between 1 and 100?  Check

Step 6: Authorization Check

Time: 0.5ms
Handler verifies:
- User owns KB with ID kb_12345?
  Query: SELECT owner_id FROM knowledgebases WHERE id=? AND tenant_id=?
  Result: owner_id="user_456", matches JWT user_id. OK

Step 7: Call SearchService

Time: 0.05ms (function call)
handler.searchService.Search(ctx, &SearchRequest{
    Query: "how to train a model",
    KnowledgeBaseID: "kb_12345",
    TopK: 10,
    UserID: "user_456",
    TenantID: "tenant_789",
})

Total Phase 3: 1.05ms

Phase 4: Search Service (3-50ms)

Step 8: Generate Query Embedding (20-25ms)

Time: 20ms
Service calls: llmService.Embed("how to train a model")
  - Check embedding cache (key = MD5(query))
  - Cache miss
  - Call OpenAI API: POST https://api.openai.com/v1/embeddings
    Request body: {"input": "how to train a model", "model": "text-embedding-3-small"}
    OpenAI latency: 18-20ms
  - Receive: embedding [0.123, -0.456, ..., 0.789] (1536 floats)
  - Cache result for 1 hour

Step 9: Vector Database Search (25-30ms)

Time: 25ms
Service calls: dao.SearchChunks(ctx, embedding, topK=10)

GORM query:
SELECT *, embedding <-> $1 as distance
FROM chunks
WHERE knowledge_base_id = $2 AND tenant_id = $3
ORDER BY distance ASC
LIMIT 10

Postgres execution:
1. IVFFlat index lookup (pgvector)  2ms
   - Find 50 nearest clusters
   - Narrow down to top 50 candidates
2. Exact distance recalculation      3ms
   - Compute L2 distance to top 50
   - Sort, take top 10
3. Fetch chunk data (SELECT)          5ms
   - Load chunks from disk into memory
   - Deserialize JSON
4. Total query time: 10ms
5. Network round-trip: 15ms

Total Step 9: 25ms

Step 10: Aggregate Results (2-3ms)

Time: 2ms
Service iterates 10 chunk results:
- Extract document_id, page_num, content
- Format as SearchResult struct
- Sort by similarity score (already done by DB)

Total Phase 4: 47ms

Phase 5: Response Formatting (50-55ms)

Step 11: Handler Builds Response

Time: 1ms
handler.buildSearchResponse(&service_result)

type SearchResponse struct {
    RequestID   string         `json:"request_id"`
    Results     []SearchResult `json:"results"`
    TotalCount  int            `json:"total_count"`
    Latency     float64        `json:"latency_ms"`
}

Step 12: JSON Marshaling

Time: 2ms
json.Marshal(response)
- Encode 10 chunks (each ~2KB) to JSON
- Total payload: ~20KB

Step 13: HTTP Response Headers

Time: 0.1ms
Set response headers:
Content-Type: application/json
Content-Length: 20480
X-Request-ID: req_xyz123

Total Phase 5: 3ms

Phase 6: Network Transmission (55-150ms)

Step 14: TLS Encryption & Send

Time: 95ms
1. Gin serializes response to TCP socket
2. Nginx encrypts response (TLS)     1ms
3. TCP transmission to browser       94ms (network I/O)
   - 20KB payload, typical RTT 50ms, assume TCP slow start
   - Actual: depends on network

Step 15: Browser Receives & Renders

Time: (not counted server-side)
1. Browser TLS decryption
2. JSON parse
3. React re-render of search results

Total Phase 6: 95ms (mostly network)

Latency Breakdown

Phase	Time	%
1. Network & TLS	1ms	1%
2. Gin routing	0.5ms	0.3%
3. Handler validation	1.05ms	0.7%
4. Search service	47ms	31%
5. Response format	3ms	2%
6. Network transmission	95ms	63%
TOTAL	147ms	100%

Where Time Is Actually Spent

Server-side (52ms, 35%)

LLM API call (20ms): Waiting for OpenAI
Database vector search (25ms): Postgres IVFFlat index + network
Everything else (7ms): Parsing, validation, formatting

Network (95ms, 65%)

LLM API network (18ms): Included in LLM call above
Database network (15ms): Included in DB search above
Response download (95ms): 20KB at typical latency

Optimization Opportunities

Low Hanging Fruit

Cache embeddings by query substring - Cache "train model", reuse for similar queries. Saves 20ms.
Implement query result caching - Cache top 10 results for exact query + KB combo. Saves 25ms (DB skip).
Pre-generate embeddings for FAQ - No LLM call for common questions. Saves 20ms.

Requires Schema Change

Reduce response payload - Compress JSON, only send essential fields. Saves ~50ms network.
Streaming responses - Send results as they arrive instead of waiting for all 10. User sees partial results in 50ms.

Not Worth It (Already Fast)

Optimize JWT validation (0.3ms) - Already using cached public key
Optimize handler parsing (0.3ms) - Negligible overhead

Code Path Reference

Handler

// handler/search.go
func (h *SearchHandler) Search(c *gin.Context) {
    var req SearchRequest
    if err := c.ShouldBindJSON(&req); err != nil {
        c.JSON(400, gin.H{"error": err.Error()})
        return
    }
    
    result, err := h.searchService.Search(c.Request.Context(), &req)
    if err != nil {
        h.logger.Error("search failed", "error", err)
        c.JSON(500, gin.H{"error": "search failed"})
        return
    }
    
    c.JSON(200, result)
}

Service

// service/search.go
func (s *SearchService) Search(ctx context.Context, req *SearchRequest) (*SearchResponse, error) {
    embedding, err := s.llmService.Embed(ctx, req.Query)
    if err != nil {
        return nil, err
    }
    
    results, err := s.dao.SearchChunks(ctx, embedding, req.TopK)
    if err != nil {
        return nil, err
    }
    
    return &SearchResponse{
        Results: results,
        Latency: time.Since(start).Seconds() * 1000,
    }, nil
}

DAO

// dao/chunk.go
func (d *DAO) SearchChunks(ctx context.Context, embedding pgvector.Vector, topK int) ([]Chunk, error) {
    var chunks []Chunk
    err := d.db.WithContext(ctx).
        Select("*, embedding <-> ? as distance", embedding).
        Where("kb_id = ? AND tenant_id = ?", d.KBID, d.TenantID).
        Order("distance ASC").
        Limit(topK).
        Find(&chunks).Error
    return chunks, err
}

Testing Performance

To measure real latency, add timing instrumentation:

// In handler
start := time.Now()
result, _ := h.searchService.Search(ctx, &req)
elapsed := time.Since(start)

c.Header("X-Server-Time", fmt.Sprintf("%dms", elapsed.Milliseconds()))

Or use middleware:

// Logging middleware
func LoggingMiddleware() gin.HandlerFunc {
    return func(c *gin.Context) {
        start := time.Now()
        c.Next()
        elapsed := time.Since(start)
        
        if elapsed > 100*time.Millisecond {
            logger.Warn("slow request", "path", c.Request.URL.Path, "ms", elapsed.Milliseconds())
        }
    }
}

Caching Strategy Impact

Cache Hit Scenario (Best Case)

t=0ms     t=5ms   t=50ms    t=100ms
|---------|-------|---------|----------|
Gin       Handler Vector    Response
Route     Validate Search    Sent
              (cache hit)

Key difference: Embedding generation (20ms) is skipped.
New latency: ~50ms (50% faster)

Cache Tuning

// Embedding cache
type EmbeddingCache struct {
    mu    sync.RWMutex
    data  map[string][]float32
    ttl   time.Duration
    size  int  // max entries
}

// Example tuning
cache := NewEmbeddingCache(
    ttl: 1*time.Hour,  // embeddings valid for 1 hour
    size: 10000,       // cache 10K queries max
)

Load Testing Results

Stress testing the search endpoint with concurrent load:

Test Configuration:
- Concurrent connections: 100
- Request rate: 1000 req/s
- Test duration: 60 seconds
- Total requests: 60,000

Results:
- p50 latency: 48ms
- p95 latency: 120ms
- p99 latency: 250ms
- Error rate: 0.01% (6 timeouts out of 60K)
- Throughput: 999 req/s (sustained)

Bottleneck Analysis:
- Database vector search is the limiting factor
- CPU usage: 60% (room to scale)
- Memory: stable at 1.2GB
- Goroutines: 500-800 (healthy)

Troubleshooting Slow Requests

Request Takes > 5 Seconds

Diagnosis: Enable verbose logging

// Add to handler
start := time.Now()
c.Set("start_time", start)
c.Next()
elapsed := time.Since(start)
if elapsed > 5*time.Second {
    c.Header("X-Slow-Request", "true")
    logger.Warn("slow request", "endpoint", c.Request.URL, "ms", elapsed.Milliseconds())
}

Common Causes & Fixes:

LLM timeout: Embedding generation hanging. Set timeout, fall back to keyword search.
Database hang: Long-running query. Check query plan with EXPLAIN ANALYZE. Add indexes if needed.
Goroutine leak: goroutine count keeps growing. Use pprof to find leak.
Network latency: Client far away, high packet loss. Add CDN or reduce payload size.

Monitoring in Production

Key Metrics to Track

// Using Prometheus
search_requests_total (counter)  // total requests since start
search_latency_seconds (histogram)  // p50, p95, p99
search_errors_total (counter)  // errors by type
active_search_requests (gauge)  // current in-flight
embedding_cache_hits_total (counter)  // cache efficacy
db_query_duration_seconds (histogram)  // database performance

Alerting

Set up alerts for production incidents:

p99 latency > 500ms → investigate database or LLM
Error rate > 1% → check logs for exceptions
Memory growth > 2GB → possible goroutine leak
Embedding cache hit rate < 50% → consider longer TTL

Code Path Reference: Detailed

For full debugging, add tracing at each step:

// handler/search.go - Add timing instrumentation
func (h *SearchHandler) Search(c *gin.Context) {
    start := time.Now()
    defer func() {
        elapsed := time.Since(start)
        logger.Info("search total", "ms", elapsed.Milliseconds())
        c.Header("X-Total-Time-Ms", fmt.Sprint(elapsed.Milliseconds()))
    }()
    
    // Step 1: Unmarshal (measure)
    t1 := time.Now()
    var req SearchRequest
    if err := c.ShouldBindJSON(&req); err != nil {
        logger.Error("unmarshal failed", "ms", time.Since(t1).Milliseconds())
        return
    }
    logger.Info("unmarshal", "ms", time.Since(t1).Milliseconds())
    
    // Step 2: Call service (measure)
    t2 := time.Now()
    result, err := h.searchService.Search(c.Request.Context(), &req)
    logger.Info("service", "ms", time.Since(t2).Milliseconds())
    
    // Step 3: Marshal response (measure)
    t3 := time.Now()
    c.JSON(200, result)
    logger.Info("marshal", "ms", time.Since(t3).Milliseconds())
}

Request Lifecycle: End-to-End Trace