Time Measurement Methods for Client VM Startup

[7174Andy]

Problem

Previously, we had remote-exec in Terraform to SSH into the client EC2 Instance to measure the time for startup (time for Terraform apply + time to finish cloud-init). However, this caused some bugs indicated in this issue: #192. Therefore, in this PR, we fixed it by removing remote-exec.

Proposed Solution

The proposed new way is to measure time for cloud-init in the user_data.sh for the client VMs. Also, we can measure the time for start.sh for Client VMs' Docker containers. These values will be stored in the database for runtime calculation in the future via RESTful API.

1. Database Modification

We need to store the values in the database is spot on. I recommend adding new columns to the existing vms table, as these metrics are
properties of a specific VM.

• Table: vms
• New Columns:
  • terraform_apply_duration_seconds: FLOAT
  • cloud_init_duration_seconds: FLOAT
  • container_startup_duration_seconds: FLOAT
• Action: Update packages/allocator/src/lablink_allocator_service/generate_init_sql.py to reflect these changes.

2. Measuring Terraform Apply Time (Allocator-side)

• Logic: In the function that runs terraform apply, record the start and end time.
• Action: Modify packages/allocator/src/lablink_allocator_service/utils/terraform_utils.py. The function that wraps the terraform apply command should be updated to time the execution and store the result in the terraform_apply_duration_seconds column for the newly created VMs.

3. Measuring on the Client VM (Client-Side)

This is the core of your proposal. We can use simple shell commands to get the timings.

• In user_data.sh:

#!/bin/bash
CLOUD_INIT_START_TIME=$(date +%s)

# ... all existing user_data commands ...
# (installing docker, pulling images, etc.)

CLOUD_INIT_END_TIME=$(date +%s)
CLOUD_INIT_DURATION=$((CLOUD_INIT_END_TIME - CLOUD_INIT_START_TIME))

# Use curl to send this metric back to the allocator
curl -X POST -H "Content-Type: application/json" \
    -d "{\"cloud_init_duration_seconds\": $CLOUD_INIT_DURATION}" \
    ${allocator_url}/vm_metrics/${hostname}

• In start.sh (inside the client Docker container):

#!/bin/bash
CONTAINER_START_TIME=$(date +%s)

# ... existing container startup logic ...
# (activating venv, starting services)

CONTAINER_END_TIME=$(date +%s)
CONTAINER_DURATION=$((CONTAINER_END_TIME - CONTAINER_START_TIME))

# Use curl to send this metric back to the allocator
curl -X POST -H "Content-Type: application/json" \
   -d "{\"container_startup_duration_seconds\": $CONTAINER_DURATION}" \
    $ALLOCATOR_URL/vm_metrics/$HOSTNAME

(Note: Assumes ALLOCATOR_URL and HOSTNAME are available as environment variables inside the container, which they should be).

4. Add Endpoints to the Allocator Web Server

• New Endpoint: POST /vm_metrics/<hostname>
• Logic: This endpoint will receive a JSON payload with one or more metric fields. It will find the corresponding VM in the vms table by
  hostname and update the appropriate duration column.
• Action: Add this new route and handler to packages/allocator/src/lablink_allocator_service/main.py.

[eberrigan]

Thanks for this proposal! I've analyzed the current implementation and have detailed recommendations for measuring VM startup times.

Current State Assessment

What exists:

• ✅ Terraform time_static resources in main.tf (lines 5-7, 105-134) already tracking infrastructure creation time
• ✅ user_data.sh with initialization steps
• ✅ start.sh for Docker container startup
• ✅ Database table structure (vms table)
• ✅ Status tracking via POST /api/vm-status endpoint

What's missing:

• ❌ Database columns for timing metrics
• ❌ API endpoint to receive metrics (POST /api/vm-metrics/<hostname>)
• ❌ Client-side timing instrumentation in user_data.sh and start.sh
• ❌ Allocator-side timing extraction from Terraform
• ❌ Database methods to store/retrieve timing data
• ❌ UI to display timing metrics

Key Findings

Terraform Already Measures Timing! The main.tf file has time_static resources and calculates per-instance duration, average, min, max (lines 110-130), but these are only shown in Terraform output, not stored in the database. We can leverage this existing infrastructure.

Recommendations

1. Enhanced Database Schema

The proposed three columns are good, but I recommend adding timestamps for better debugging:

# In generate_init_sql.py
CREATE TABLE IF NOT EXISTS {VM_TABLE} (
    HostName VARCHAR(1024) PRIMARY KEY,
    Pin VARCHAR(1024),
    CrdCommand VARCHAR(1024),
    UserEmail VARCHAR(1024),
    InUse BOOLEAN NOT NULL DEFAULT FALSE,
    Healthy VARCHAR(1024),
    Status VARCHAR(1024),
    Logs TEXT,
    -- New timing columns
    TerraformApplyStartTime TIMESTAMP,
    TerraformApplyEndTime TIMESTAMP,
    TerraformApplyDurationSeconds FLOAT,
    CloudInitStartTime TIMESTAMP,
    CloudInitEndTime TIMESTAMP,
    CloudInitDurationSeconds FLOAT,
    ContainerStartTime TIMESTAMP,
    ContainerEndTime TIMESTAMP,
    ContainerStartupDurationSeconds FLOAT,
    TotalStartupDurationSeconds FLOAT,
    CreatedAt TIMESTAMP DEFAULT NOW()
);

Why timestamps + duration?

• Timestamps enable chronological analysis and debugging
• Duration provides quick metrics for dashboards
• Can recalculate/validate duration from timestamps if needed

2. Leverage Existing Terraform Timing

Since Terraform already calculates timing in locals, we should extract it rather than re-implement:

Add to outputs.tf:

output "instance_startup_times" {
  value = {
    for i in range(var.instance_count) :
    aws_instance.lablink_vm[i].tags.Name => {
      seconds = local.per_instance_seconds[i]
      formatted = local.per_instance_hms[i]
    }
  }
}

Modify launch() function in main.py (after line 426):

# After terraform apply succeeds
timing_output = subprocess.run(
    ["terraform", "output", "-json", "instance_startup_times"],
    cwd=TERRAFORM_DIR, capture_output=True, text=True, check=True
)
timing_data = json.loads(timing_output.stdout)

# Store in database for each VM
for hostname, metrics in timing_data.items():
    database.update_terraform_timing(
        hostname=hostname,
        duration_seconds=metrics['seconds'],
        end_time='NOW()'
    )

Why this approach?

• More accurate (measures per-instance, even when creating multiple VMs in parallel)
• Reuses existing Terraform functionality
• No additional timing overhead

3. Client-Side Instrumentation

A. In user_data.sh

Add at the very beginning (after line 2):

#!/bin/bash
set -euo pipefail

# Start timing cloud-init
CLOUD_INIT_START=$(date +%s)

Add at the very end (after line 165, after container launch):

CLOUD_INIT_END=$(date +%s)
CLOUD_INIT_DURATION=$((CLOUD_INIT_END - CLOUD_INIT_START))

curl -s -X POST "$ALLOCATOR_URL/api/vm-metrics/$VM_NAME" \
    -H "Content-Type: application/json" \
    -d "{
        \"cloud_init_start\": $CLOUD_INIT_START,
        \"cloud_init_end\": $CLOUD_INIT_END,
        \"cloud_init_duration_seconds\": $CLOUD_INIT_DURATION
    }" --max-time 5 || true

echo ">> Cloud-init completed in $CLOUD_INIT_DURATION seconds"

B. In start.sh

Add after line 3:

CONTAINER_START=$(date +%s)

Add after all services start (after line 64, before tail):

CONTAINER_END=$(date +%s)
CONTAINER_DURATION=$((CONTAINER_END - CONTAINER_START))

curl -s -X POST "${ALLOCATOR_URL}/api/vm-metrics/${VM_NAME}" \
    -H "Content-Type: application/json" \
    -d "{
        \"container_start\": $CONTAINER_START,
        \"container_end\": $CONTAINER_END,
        \"container_startup_duration_seconds\": $CONTAINER_DURATION
    }" --max-time 5 || true

echo "Container startup completed in $CONTAINER_DURATION seconds"

Note: Using || true ensures timing failures don't break VM startup.

4. API Endpoint Implementation

Add to main.py:

@app.route("/api/vm-metrics/<hostname>", methods=["POST"])
def receive_vm_metrics(hostname):
    """Receive and store VM timing metrics."""
    try:
        data = request.get_json()

        if not database.vm_exists(hostname):
            logger.error(f"VM with hostname {hostname} not found.")
            return jsonify({"error": "VM not found."}), 404

        # Update timing metrics
        database.update_vm_metrics(hostname=hostname, metrics=data)

        # Calculate total startup time if all phases complete
        database.calculate_total_startup_time(hostname)

        logger.info(f"Received metrics for {hostname}: {data}")
        return jsonify({"message": "Metrics updated successfully."}), 200

    except Exception as e:
        logger.error(f"Error receiving VM metrics: {e}")
        return jsonify({"error": "Failed to update metrics."}), 500

5. Database Methods

Add to database.py:

def update_vm_metrics(self, hostname: str, metrics: dict) -> None:
    """Update timing metrics for a VM."""
    updates = []
    values = []

    if "cloud_init_start" in metrics:
        updates.append("CloudInitStartTime = to_timestamp(%s)")
        values.append(metrics["cloud_init_start"])
    if "cloud_init_end" in metrics:
        updates.append("CloudInitEndTime = to_timestamp(%s)")
        values.append(metrics["cloud_init_end"])
    if "cloud_init_duration_seconds" in metrics:
        updates.append("CloudInitDurationSeconds = %s")
        values.append(metrics["cloud_init_duration_seconds"])

    if "container_start" in metrics:
        updates.append("ContainerStartTime = to_timestamp(%s)")
        values.append(metrics["container_start"])
    if "container_end" in metrics:
        updates.append("ContainerEndTime = to_timestamp(%s)")
        values.append(metrics["container_end"])
    if "container_startup_duration_seconds" in metrics:
        updates.append("ContainerStartupDurationSeconds = %s")
        values.append(metrics["container_startup_duration_seconds"])

    if not updates:
        return

    query = f"UPDATE {self.table_name} SET {', '.join(updates)} WHERE hostname = %s"
    values.append(hostname)

    try:
        self.cursor.execute(query, values)
        self.conn.commit()
        logger.debug(f"Updated metrics for VM '{hostname}'.")
    except Exception as e:
        logger.error(f"Error updating metrics: {e}")
        self.conn.rollback()

def update_terraform_timing(self, hostname: str, duration_seconds: float, end_time: str = 'NOW()') -> None:
    """Update Terraform apply timing for a VM."""
    query = f"""
        UPDATE {self.table_name}
        SET TerraformApplyDurationSeconds = %s,
            TerraformApplyEndTime = {end_time}
        WHERE hostname = %s
    """
    try:
        self.cursor.execute(query, (duration_seconds, hostname))
        self.conn.commit()
        logger.debug(f"Updated Terraform timing for VM '{hostname}': {duration_seconds}s")
    except Exception as e:
        logger.error(f"Error updating Terraform timing: {e}")
        self.conn.rollback()

def calculate_total_startup_time(self, hostname: str) -> None:
    """Calculate and store total startup time from all phases."""
    query = f"""
        UPDATE {self.table_name}
        SET TotalStartupDurationSeconds =
            COALESCE(TerraformApplyDurationSeconds, 0) +
            COALESCE(CloudInitDurationSeconds, 0) +
            COALESCE(ContainerStartupDurationSeconds, 0)
        WHERE hostname = %s AND
              TerraformApplyDurationSeconds IS NOT NULL AND
              CloudInitDurationSeconds IS NOT NULL AND
              ContainerStartupDurationSeconds IS NOT NULL
    """
    try:
        self.cursor.execute(query, (hostname,))
        self.conn.commit()

        # Log the total time
        result_query = f"SELECT TotalStartupDurationSeconds FROM {self.table_name} WHERE hostname = %s"
        self.cursor.execute(result_query, (hostname,))
        total = self.cursor.fetchone()
        if total and total[0]:
            logger.info(f"Total startup time for {hostname}: {total[0]:.1f}s")
    except Exception as e:
        logger.error(f"Error calculating total startup time: {e}")
        self.conn.rollback()

6. UI Enhancement

Modify instances.html to display timing:

<th>Terraform</th>
<th>Cloud-Init</th>
<th>Container</th>
<th>Total Time</th>

<!-- In table body -->
<td>{{ "%.1f"|format(instance.TerraformApplyDurationSeconds or 0) }}s</td>
<td>{{ "%.1f"|format(instance.CloudInitDurationSeconds or 0) }}s</td>
<td>{{ "%.1f"|format(instance.ContainerStartupDurationSeconds or 0) }}s</td>
<td><strong>{{ "%.1f"|format(instance.TotalStartupDurationSeconds or 0) }}s</strong></td>

7. Important Considerations

A. Timing Phases Overlap

• Cloud-init runs user_data.sh which launches Docker container
• Container startup begins before cloud-init completes
• Total time ≠ sum of phases (there's overlap)

Solution: The timestamps show the actual timeline. Total calculation shows sequential sum for comparison purposes.

B. Failure Handling

• What if user_data.sh fails before posting metrics?
• What if network is down when posting?

Solution: Metrics posting uses || true (best-effort). Missing metrics indicate potential issues. The existing status tracking (initializing → running) serves as a fallback indicator.

C. Multiple VMs in Parallel

• Terraform creates multiple VMs simultaneously
• Per-instance timing from Terraform's time_static is accurate
• Network timing may vary between VMs

Solution: Store per-VM metrics separately; calculate aggregate statistics in queries.

Implementation Checklist

• Database schema: Add timing columns to generate_init_sql.py
• Database methods: Add update_vm_metrics(), update_terraform_timing(), calculate_total_startup_time()
• Terraform outputs: Add instance_startup_times output
• Allocator timing: Extract and store Terraform timing in launch()
• API endpoint: Add POST /api/vm-metrics/<hostname>
• user_data.sh: Add timing instrumentation
• start.sh: Add timing instrumentation
• UI: Add timing columns to instances view
• Testing: Verify metrics for single and multiple VM creation
• Documentation: Update CLAUDE.md with timing metrics

Estimated effort: 8-12 hours total

Benefits

1. Granular visibility: See exactly where time is spent (infrastructure vs initialization vs container)
2. Performance optimization: Identify bottlenecks in startup process
3. Regression detection: Track if changes slow down VM creation
4. User feedback: Provide accurate ETA for VM readiness
5. Historical data: Analyze trends over time

---

Analysis by Elizabeth + Claude