Implement workload simulator for autoscaler development

[jchesterpivotal]

/area autoscale
/area dev

Introduction

Autoscaling is a surprisingly difficult problem with a number of nested and overlapping problems to solve. In developing solutions, we can aim to validate or invalidate our design hypotheses in three main ways:

• Empirically
  • From production observations
  • From load & performance testing
• Theoretically
  • Applying control theory
  • Applying queueing theory
• With simulation

This proposal addresses the third validation approach.

Why simulation?

Because each validation approach has different strengths and weaknesses. Empirical validation is the final word, but is a slow-moving feedback loop (hours to months). Theoretical validation can dramatically shrink the solution search space, but is less accessible to each of our key personae (developers, operators, contributors) and does not yet address problems that remain unsolved in the research literature.

Simulation splits the difference: it is faster than empirical validation with the risk of inaccuracy, simpler than theoretical validation with the cost of implementation. Simulation is intended to provide contributors with the ability to rapidly explore the design space and iterate on solutions. It is also intended to illuminate potential problems in advance of implementation. Simulation will probably provide input into autoscaling, routing, serving and upstream projects.

Previous and related work

Project riff

For Project riff, I and @glyn developed a simple workload simulator[0][1] for the original riff autoscaler implementation.

This simulator walks the autoscaler implementation through three basic traffic scenarios: a step function (to test behaviour under traffic spikes), a linear ramp-up and ramp-down (to test smoothness of response under ideal conditions), and a sinusoidal function (behaviour in the face of yo-yo attacks).

It then produces simple charts of behaviour to allow for manual inspection and characterisation of autoscaler reaction. We had intended to extend the design to allow for more advanced applications -- for example, statistical characterisations (volatility, P99 etc) to quickly detect regressions in performance.

Within Knative

Related issues include:

• "Load-/Performance test methodology"
• "Gather requirements/determine config surface for autoscaling"
• "Min and Max Pods"
• "Vertical Pod Autoscaling"
• "Mitigate / Eliminate image pull latency"

Related documents for which simulation may help test hypotheses:

• "Levels of Heat + Knative Autoscaling"
• "Automatic decomposition of filesystems into layers for runtime reassembly"

In the literature

Autoscaling literature is quite energetic, but mostly focuses on predictive scaling. Using techniques such as fast fourier transforms, linear regressions, neural nets and the like, researchers have been able to forecast future demand under conditions of predictable variation.

For example:

• Netflix Scryer[0][1]
• "Self-Learning Cloud Controllers: Fuzzy Q-Learning for Knowledge Evolution"
• "WAM - The Weighted Average Method for Predicting the Performance of Systems with Bursts of Customer Sessions"

Less well-treated (based on cursory searching) has been reactive autoscaling of the kind we're working on here. In Project riff we were looking at applications of basic control theory (inspired by Feedback Control for Computer Systems: Introducing Control Theory to Enterprise Programmers by Phillipp K. Janert). We had begun to investigate applications of queueing theory (for which see Performance Modeling and Design of Computer Systems: Queueing Theory in Action by Mor Harchol-Balter).

Proposed approach

Internals

It may be easier to reimplement a simulator than to adapt riff's existing simulator.

The existing design is a fixed time step simulation. It updates all parts of the simulation at each time slice.

A reimplementation should instead develop a next event time simulation. These run faster than continuous-time simulations as they are able to skip time slices during which nothing interesting has occurred.

Usage

The current graphs output by the riff simulator are generated by gnuplot. This was useful for rapid iteration, but gnuplot's language can be a bit arcane. It also stands somewhat aside from larger data science and analysis ecosystems. It may be easier to focus on spitting out raw data and then leaving graphing and analysis to other tools.

In particular, we should aim to have a uniform approach for analysing both simulated and empirical cases.

Further out

In the longer run, we may be able to continuously search the design and configuration space with Monte Carlo methods. We also ought to test for simulated regressions during local tests as a fast first feedback loop to contributors.

[jchesterpivotal]

/assign

[jchesterpivotal]

It's worth reporting on progress so far. I've developed two different "simulators": a prototype and a discrete-event simulator.

(The codebase is not currently public. I hope to remedy that soon.)

The prototype simulator

The prototype explored two aspects:

1. What is the controllable API surface of the autoscaler system?
2. How can simulation results be graphically displayed?

The prototype works as a fixed-increment simulation. Each iteration of the simulation loop advances time by a fixed increment of 1 second. At each step the simulation decides whether to change the variables observed by the autoscaler system: how many Endpoints are active and how many requests are being concurrently handled. It captures the scaling decisions of the autoscaler.

The statistics for each step are gathered and output into a simple graph of simulation.

Problems with the prototype simulator

The first problem is that the simulation is unrealistic, parts of it are "faked". The times at which the controlled variables are changed are all hardcoded.

The second problem is the fixed-increment approach itself. For large parts of the simulation, none of the variables have changed. An iteration of the simulation loop where nothing changes is basically wasted effort. This doesn't matter with the small scenario used (1000 increments of 1 second each), but will become worse as the scenarios grow longer or as precision grows finer.

The third and more serious problem is that the timeline of the simulation is only partially under simulator control. The statistics given to the autoscaler are timestamped based on the simulator's scenario. But the autoscaler itself keeps internal time which is not controlled. Results are inconsistent because the autoscaler assumes events are occurring in a real clock time and bucketizes statistics on that basis. Meanwhile the simulator is injecting timestamped statistics at a faster-than-clock-time pace.

As the simulator effort proceeds, there will need to be a way for the simulation to directly control the time perceived by the autoscaler's decision system.

Discrete event simulator harness

Discrete event simulation is based on the idea that the simulated system proceeds from state to a successor state a specific points of time; these are the "discrete events". This assumption enables next-event simulation. In next-event simulation, events are placed into a "Future Event List" (FEL), typically a priority queue, ordered by the timestamp of when they are going to occur.

This has two key performance implications:

1. Events can be added to the FEL independently by multiple processes.
2. The simulation can "skip" the simulation clock forward to the timestamp of the next event in the list (hence "next-event").

This means that simulation time becomes proportional to the number of events, not the number of increments. Time can be modeled with arbitrary precision without increasing running time. A simulation at nanosecond precision takes approximately the same time to run as a simulation at second precision.

My main reference for this work has been Simulation Modeling & Analysis, 5e by Averill M. Law. In the first two chapters it gives a detailed description of an implementation, including sample C source. Other textbooks in this area appear to have similar contents.

The design outlined has the Future Events List (FEL). The FEL is iterated over by a single function which then reacts based on a single switch statement. In each branch of the switch, various global variables are manipulated which represent the modeled system.

I'm not a big fan of having a single switch that manages global variables. In the book Law mentions "process-oriented" discrete event simulation as an alternative. The difference appears to be that a process-oriented approach models represent individual entities in the system, rather than manipulating global variables. But the description given is confined to a few paragraphs; no example implementation is discussed. My very light searches of literature did not turn up any other work which describes implementation of process-oriented systems with the level of detail the textbook devotes to the switch/global implementation. The closest I found was tutorial literature for the SimPy simulation library. There is an extensive literature on parallel simulation using multiple event lists and what appear to be various kinds of consensus protocols. However I judged these as not immediately applicable to my work.

My current approach retains a single FEL, managed by an Environment (this concept is borrowed from SimPy). Different entities can schedule events with the Environment. Each event contains its name, timestamp and a pointer to a callback function, Advance.

As events occur, their name and timestamp is passed into the Advance callback function. Each entity applies the event to an internal finite state machine (represented using the looplab/fsm library). Some of them also have additional logic based on the event that has occurred.

Most often, this involves scheduling a subsequent action for the same entity. For example, the Executable entity represents the "warmth hierarchy" for software delivered using container images. The first event pushed into the FEL by an Executable is begin_pulling. When this event is applied, the Executable will schedule a finish_pulling event that is intended to occur 90 seconds later in the simulated time, as well as applying the event to its internal state machine (moving from StateDeadCold to StatePulling).

Problems with the discrete event simulator

Event ordering

The main problem is event ordering across multiple interacting entities with their own timelines.

Take Executable: it is a largely self-contained representation. Considered alone, each event in its lifecycle triggers the scheduling of the next event; it should not know about other kinds of entity.

But consider the Replica entity, made distinct from the Executable so that multiple Replicas could potentially use and reuse the same Executable.

It violates the basic causality of the model if a Replica becomes StateReplicaActive before the relevant Executable has reached StateLiveProcess. Every Replica should be blocked until its Executable is ready. To achieve this causal ordering in the current implementation, the Executable becomes responsible for scheduling events for both itself (eg finish_launching_process) as well as events for a Replica (eg finish_launching_replica). This is an unattractive coupling, both in terms of direct variable references between entities and in terms of needing to know implementation details of other entities.

Slight FSM clunkiness

The representation for FSMs provides the basic features I need (states, events, transitions). But I am uncertain whether it has the precise representation I would like. In particular, most states in the system will have limited lifetimes, but there's no inbuilt notion of "this state will last for X duration", without needing to do the event-creation plumbing myself.

I'm not sure if this is a real difficulty or just a mild annoyance.

What's next?

The simulator harness

The simulator harness itself needs to solve the ordering problem without coupling entities so closely. I have been considering how.

One option would be to allow the event time to be resolved after scheduling has occurred -- a rule could be provided saying "X will happen after a currently-unknown Y, plus Z additional duration". This still requires entities to know about each other's event types, but will remove some of the conditional logic currently sprinkled across different Advance functions. Events without known timestamps would be placed into an Unknown Future List, and moved across to the FEL once they could be resolved. This might have the drawback of causing additional work to occur on every event in order to check if candidates are available to promote into the FEL.

Another option would be that entities could subscribe not just to events being popped from the FEL, but to events being pushed into the List. For example, a Replica might register interest in any finish_launching_process events scheduled by its relevant Executable. As soon as it becomes known when a finish_launching_process event will occur, the Replica can schedule its own finish_launching_replica event to follow. This option still requires entities to know something about each other's event types, but it would probably perform better than the two-List option described above.

The autoscaler API surface

As noted above, the autoscaler keeps its own schedule for making scaling decisions. The simulation effort will need some way to control this perception of time so that intermediate time intervals may be skipped.

Currently the simulator harness does not drive the autoscaler directly. It has been necessary to work on the more abstract part of the system before marrying the two elements. I expect that point will lead to discoveries of other impedance mismatches.

Statistics

The harness does not collect any statistics. I had deferred this question to focus on its design. However without collecting figures, it will not be useful for its original purpose of allowing easier study of behaviour under different
conditions.

Code quality

The current codebase is consciously a spike: an exploratory effort intended to help me understand the problems better. When I feel confident I have solved the design problems above, it will be time to put the first codebase aside and reimplement the design in a proper test-first manner.

[jchesterpivotal]

A quick update from where I was last week. I made two major changes.

Listening for events being scheduled

I added a concept of listening for an event being scheduled, but not having yet occurred. This allows various entities to schedule their events ahead and behind other events from cooperating entities.

Stock Movement

I introduced a concept of "Stock Movement", where a Stockable entity moves from one Stock to another.

It's currently an extension of the pre-existing Event mechanism, now split into GeneralEvent and StockMovementEvent. I'm not a huge fan of how this turned out. I think I still assume that languages have generics and method overriding; then they turn out not to and I hate all the alternatives.

This solved one class of problems (how does a Request know where it is? How does it wait for a Replica to become ready?), but now I have a bunch of duplicated logic. Sometimes I use plain events and OnOccurrence. Sometimes I use StockMovementEvents, in turn driving the Environment to call Stockable.OnMovement() and Stock.UpdateStock().

At the start it seemed that some things are state-y and some things are movement-y. For example, a Request that is in StateRequestProcessing is, in some sense, not moving. But if you push at it, it can be modeled as having moved from a ReplicaRequestWaitingPool to a ReplicaRequestProcessingPool.

I'm now kicking around the idea that next week, I may try to push through to reunifying the event types and making everything movement-based. This may also simplify Executable, the first type I developed. On the downside I'll need to create models at finer granularity -- for example, an Executive needs to know that it is first in a registry, then being streamed over a network, then on a disk, then in RAM, then in a process table. Currently this is a relatively compact FSM; with stock-and-flow there is more boilerplate. But the flipside is that when begin to properly model WorkerNodes, it will be easier to have multiple Executables correctly modeled.

It scales!

Here I bury the lede a bit. I now have the Knative Autoscaler receiving statistics from simulated components and making decisions which are acted on by other simulated components. Here's a trace of one of the first runs that worked end-to-end:

=== BEGIN TRACE ===============================================================================================================================================
             TIME (ns)    IDENTIFIER          EVENT                         FROM STATE                -->  TO STATE                     NOTE
---------------------------------------------------------------------------------------------------------------------------------------------------------------
G                    0    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        
G                    1    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
G       60,000,000,001    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        There was an error in scaling
G       60,000,000,002    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
M       79,410,000,000    req-023082153551    buffer_request                Traffic                   -->  KBuffer                      
G      120,000,000,002    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        Scaling up from 0 to 1
G      120,000,000,003    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
G      120,010,000,002    replica-458676      launch_replica                ReplicaNotLaunched        -->  ReplicaLaunching             
G      120,057,000,002    exec-188110         begin_pulling                 DeadCold                  -->  Pulling                      
M      125,231,000,000    req-094235010051    buffer_request                Traffic                   -->  KBuffer                      
M      139,168,000,000    req-024549167320    buffer_request                Traffic                   -->  KBuffer                      
2019-03-22T17:22:25.992-0400	INFO	autoscaler/autoscaler.go:203	PANICKING
2019-03-22T17:22:25.992-0400	INFO	autoscaler/autoscaler.go:218	Increasing pods from 0 to 5.
G      180,000,000,003    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        Scaling up from 1 to 5
G      180,000,000,004    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
G      180,010,000,003    replica-343014      launch_replica                ReplicaNotLaunched        -->  ReplicaLaunching             
G      180,018,000,003    exec-194511         begin_pulling                 DeadCold                  -->  Pulling                      
G      180,039,000,003    exec-7727           begin_pulling                 DeadCold                  -->  Pulling                      
G      180,041,000,003    exec-625526         begin_pulling                 DeadCold                  -->  Pulling                      
G      180,100,000,003    exec-139903         begin_pulling                 DeadCold                  -->  Pulling                      
M      208,926,000,000    req-017331776148    buffer_request                Traffic                   -->  KBuffer                      
G      210,057,000,002    exec-188110         finish_pulling                Pulling                   -->  DiskWarm                     
G      211,057,000,002    exec-188110         launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      221,057,000,002    exec-188110         finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      221,067,000,002    replica-458676      finish_launching_replica      ReplicaLaunching          -->  ReplicaActive                
M      221,077,000,002    replica-458676      add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
M      226,142,000,000    req-040480279449    buffer_request                Traffic                   -->  KBuffer                      
M      226,142,000,001    req-017331776148    send_to_replica               KBuffer                   -->  replica-458676               
M      226,142,000,002    req-040480279449    send_to_replica               KBuffer                   -->  replica-458676               
M      226,142,000,003    req-023082153551    send_to_replica               KBuffer                   -->  replica-458676               
M      226,142,000,004    req-094235010051    send_to_replica               KBuffer                   -->  replica-458676               
M      226,142,000,005    req-024549167320    send_to_replica               KBuffer                   -->  replica-458676               
G      226,152,000,001    req-017331776148    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      226,152,000,002    req-040480279449    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      226,152,000,003    req-023082153551    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      226,152,000,004    req-094235010051    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      226,152,000,005    req-024549167320    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      226,652,000,001    req-017331776148    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 17726ms
G      226,652,000,002    req-040480279449    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 510ms
G      226,652,000,003    req-023082153551    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 147242ms
G      226,652,000,004    req-094235010051    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 101421ms
G      226,652,000,005    req-024549167320    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 87484ms
2019-03-22T17:22:25.993-0400	INFO	autoscaler/autoscaler.go:218	Increasing pods from 0 to 10.
G      240,000,000,004    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        Scaling up from 5 to 10
G      240,000,000,005    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
G      240,010,000,004    replica-629109      launch_replica                ReplicaNotLaunched        -->  ReplicaLaunching             
G      240,034,000,004    exec-425286         begin_pulling                 DeadCold                  -->  Pulling                      
G      240,043,000,004    exec-566362         begin_pulling                 DeadCold                  -->  Pulling                      
G      240,067,000,004    exec-517852         begin_pulling                 DeadCold                  -->  Pulling                      
G      240,100,000,004    exec-515673         begin_pulling                 DeadCold                  -->  Pulling                      
G      240,109,000,004    exec-44359          begin_pulling                 DeadCold                  -->  Pulling                      
G      270,018,000,003    exec-194511         finish_pulling                Pulling                   -->  DiskWarm                     
G      270,039,000,003    exec-7727           finish_pulling                Pulling                   -->  DiskWarm                     
G      270,041,000,003    exec-625526         finish_pulling                Pulling                   -->  DiskWarm                     
G      270,100,000,003    exec-139903         finish_pulling                Pulling                   -->  DiskWarm                     
G      271,018,000,003    exec-194511         launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      271,039,000,003    exec-7727           launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      271,041,000,003    exec-625526         launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      271,100,000,003    exec-139903         launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      281,018,000,003    exec-194511         finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      281,028,000,003    replica-896665      finish_launching_replica      ReplicaNotLaunched        -->  ReplicaNotLaunched           
M      281,038,000,003    replica-896665      add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
G      281,039,000,003    exec-7727           finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      281,041,000,003    exec-625526         finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      281,049,000,003    replica-68135       finish_launching_replica      ReplicaNotLaunched        -->  ReplicaNotLaunched           
G      281,051,000,003    replica-343014      finish_launching_replica      ReplicaLaunching          -->  ReplicaActive                
M      281,059,000,003    replica-68135       add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
M      281,061,000,003    replica-343014      add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
G      281,100,000,003    exec-139903         finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      281,110,000,003    replica-633331      finish_launching_replica      ReplicaNotLaunched        -->  ReplicaNotLaunched           
M      281,120,000,003    replica-633331      add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
G      300,000,000,005    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        
G      300,000,000,006    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
M      324,226,000,000    req-064263669287    buffer_request                Traffic                   -->  KBuffer                      
M      324,226,000,001    req-064263669287    send_to_replica               KBuffer                   -->  replica-896665               
G      324,236,000,001    req-064263669287    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      324,736,000,001    req-064263669287    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 510ms
G      330,034,000,004    exec-425286         finish_pulling                Pulling                   -->  DiskWarm                     
G      330,043,000,004    exec-566362         finish_pulling                Pulling                   -->  DiskWarm                     
G      330,067,000,004    exec-517852         finish_pulling                Pulling                   -->  DiskWarm                     
G      330,100,000,004    exec-515673         finish_pulling                Pulling                   -->  DiskWarm                     
G      330,109,000,004    exec-44359          finish_pulling                Pulling                   -->  DiskWarm                     
G      331,034,000,004    exec-425286         launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      331,043,000,004    exec-566362         launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      331,067,000,004    exec-517852         launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      331,100,000,004    exec-515673         launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      331,109,000,004    exec-44359          launch_from_disk              DiskWarm                  -->  LaunchingFromDisk            
G      341,034,000,004    exec-425286         finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      341,043,000,004    exec-566362         finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      341,044,000,004    replica-474622      finish_launching_replica      ReplicaNotLaunched        -->  ReplicaNotLaunched           
G      341,053,000,004    replica-91161       finish_launching_replica      ReplicaNotLaunched        -->  ReplicaNotLaunched           
M      341,054,000,004    replica-474622      add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
M      341,063,000,004    replica-91161       add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
G      341,067,000,004    exec-517852         finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      341,077,000,004    replica-972129      finish_launching_replica      ReplicaNotLaunched        -->  ReplicaNotLaunched           
M      341,087,000,004    replica-972129      add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
G      341,100,000,004    exec-515673         finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      341,109,000,004    exec-44359          finish_launching_process      LaunchingFromDisk         -->  LiveProcess                  
G      341,110,000,004    replica-86785       finish_launching_replica      ReplicaNotLaunched        -->  ReplicaNotLaunched           
G      341,119,000,004    replica-629109      finish_launching_replica      ReplicaLaunching          -->  ReplicaActive                
M      341,120,000,004    replica-86785       add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
M      341,129,000,004    replica-629109      add_replica_to_kbuffer        Cluster                   -->  KBuffer                      
G      360,000,000,006    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        
G      360,000,000,007    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
M      415,800,000,000    req-075414458836    buffer_request                Traffic                   -->  KBuffer                      
M      415,800,000,001    req-075414458836    send_to_replica               KBuffer                   -->  replica-458676               
G      415,810,000,001    req-075414458836    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      416,310,000,001    req-075414458836    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 510ms
G      420,000,000,007    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        
G      420,000,000,008    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
M      461,315,000,000    req-083838182873    buffer_request                Traffic                   -->  KBuffer                      
M      461,315,000,001    req-083838182873    send_to_replica               KBuffer                   -->  replica-972129               
G      461,325,000,001    req-083838182873    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      461,825,000,001    req-083838182873    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 510ms
G      480,000,000,008    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        
G      480,000,000,009    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
M      506,283,000,000    req-074910584091    buffer_request                Traffic                   -->  KBuffer                      
M      506,283,000,001    req-074910584091    send_to_replica               KBuffer                   -->  replica-91161                
G      506,293,000,001    req-074910584091    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      506,793,000,001    req-074910584091    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 510ms
M      517,073,000,000    req-013853353331    buffer_request                Traffic                   -->  KBuffer                      
M      517,073,000,001    req-013853353331    send_to_replica               KBuffer                   -->  replica-474622               
G      517,083,000,001    req-013853353331    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      517,583,000,001    req-013853353331    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 510ms
G      540,000,000,009    autoscaler-1        calculate_scale               AutoscalerWaiting         -->  AutoscalerCalculating        
G      540,000,000,010    autoscaler-1        wait_for_next_calculation     AutoscalerCalculating     -->  AutoscalerWaiting            
M      595,346,000,000    req-035138149956    buffer_request                Traffic                   -->  KBuffer                      
M      595,346,000,001    req-035138149956    send_to_replica               KBuffer                   -->  replica-896665               
G      595,356,000,001    req-035138149956    begin_request_processing      RequestSendingToReplica   -->  RequestProcessing            
G      595,856,000,001    req-035138149956    finish_request_processing     RequestProcessing         -->  RequestFinished              Request took 510ms
M      599,990,000,002    replica-458676      remove_replica_from_kbuffer    KBuffer                   -->  Cluster                      
G      600,000,000,000    Environment         terminate_simulation          SimulationRunning         -->  SimulationTerminated         Reached termination event
---------------------------------------------------------------------------------------------------------------------------------------------------------------
Events ignored due to termination:
       600,000,000,002    replica-458676      terminate_replica         
       659,990,000,003    replica-633331      remove_replica_from_kbuffer
       660,000,000,003    replica-633331      terminate_replica         
       659,990,000,003    replica-896665      remove_replica_from_kbuffer
       660,000,000,003    replica-896665      terminate_replica         
       659,990,000,003    replica-68135       remove_replica_from_kbuffer
       660,000,000,003    replica-68135       terminate_replica         
       659,990,000,003    replica-343014      remove_replica_from_kbuffer
       660,000,000,003    replica-343014      terminate_replica         
       719,990,000,004    replica-86785       remove_replica_from_kbuffer
       720,000,000,004    replica-86785       terminate_replica         
       719,990,000,004    replica-91161       remove_replica_from_kbuffer
       720,000,000,004    replica-91161       terminate_replica         
       719,990,000,004    replica-474622      remove_replica_from_kbuffer
       720,000,000,004    replica-474622      terminate_replica         
       719,990,000,004    replica-972129      remove_replica_from_kbuffer
       720,000,000,004    replica-972129      terminate_replica         
       719,990,000,004    replica-629109      remove_replica_from_kbuffer
       720,000,000,004    replica-629109      terminate_replica         
       600,000,000,010    autoscaler-1        calculate_scale           
=== END TRACE =================================================================================================================================================
Sim clock duration:  10m0s
Real clock duration: 3.539226ms

[glyn]

Basic question: what does the first column of the trace represent (the "G"s and "M"s)?

[jchesterpivotal]

Oh right! 'G' is a GeneralEvent, M is a StockMovementEvent.

The trace output will probably change. I spent some time working up diagrams of how a more completely "stock-and-flow" approach might look (I'll attach some links momentarily). I'm hoping to perform that conversion this week.

[jchesterpivotal]

Click through for fullsize images.

[jchesterpivotal]

For those still following along, there's now an open repo that I'm working out of: https://github.com/pivotal/skenario

The key evolution in the design is that the organising concept is the movement of entities between stocks. The future-scheduling concept is retained. So far I've managed to avoid introducing OnSchedule or different "event" types. I added OnMovement, but I believe this was a design mistake and I can do without it.

In terms of implementation I've discarded the previous prototype / spike code and worked my way back with tests. It's lacking fully outside-in testing (and most bugs have only surfaced at the feature level), but there's reasonably good unit coverage.

[jchesterpivotal]

I'm now working entirely out of the Skenario repo, so I think this issue can safely be closed.