Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Verbose Simulation Output #295

Closed
wants to merge 1 commit into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
29 changes: 15 additions & 14 deletions SIMULATOR.md
Original file line number Diff line number Diff line change
Expand Up @@ -12,20 +12,6 @@ network layers are both fully simulated and do not match real instances 1:1.
The simulator uses runbooks to control some of the underlying simulations such
as p2p network latency, block production, upkeep schedules, and more.

## Profiling

Start the service in one terminal window and run the pprof tool in another. For
more information on pprof, view some docs
[here](https://github.com/google/pprof/blob/main/doc/README.md) to get started.

```
# terminal 1
$ ./bin/simulator --pprof --simulate -f ./tools/simulator/plans/simplan_fast_check.json

# terminal 2
$ go tool pprof -top http://localhost:6060/debug/pprof/heap
```

## Usage

The current iteration of the simulator requires a full build before a run as the
Expand All @@ -50,11 +36,26 @@ $ ./bin/simulator --simulate -f ./tools/simulator/plans/simplan_fast_check.json
*Options*
- `--simulation-file | -f [string]`: default ./simulation_plan.json, path to JSON file defining simulation parameters
- `--output-directory | -o [string]`: default ./simulation_logs, path to output directory where run logs are written
- `--verbose [bool]`: default false, make output verbose (prints logs to output directory)
- `--simulate [bool]`: default false, run simulation and output results
- `--charts [bool]`: default false, start and run charts service to display results
- `--pprof [bool]`: default false, run pprof server on simulation startup
- `--pprof-port [int]`: default 6060, port to serve pprof profiler on

## Profiling

Start the service in one terminal window and run the pprof tool in another. For
more information on pprof, view some docs
[here](https://github.com/google/pprof/blob/main/doc/README.md) to get started.

```
# terminal 1
$ ./bin/simulator --pprof --simulate -f ./tools/simulator/plans/simplan_fast_check.json

# terminal 2
$ go tool pprof -top http://localhost:6060/debug/pprof/heap
```

## Simulation Plan

A simulation plan is a set of configurations for the simulator defined in a JSON file and is designed to produce a
Expand Down
3 changes: 2 additions & 1 deletion cmd/simulator/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ import (
var (
simulationFile = flag.StringP("simulation-file", "f", "./simulation_plan.json", "file path to read simulation config from")
outputDirectory = flag.StringP("output-directory", "o", "./simulation_plan_logs", "directory path to output log files")
verbose = flag.BoolP("verbose", "v", false, "make output verbose (prints logs to output directory)")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about having 2 flags here:

  1. log level (info/debug/warn/error/none)
  2. log output (, "." for outputDirectory or none for CLI)
  • i.e. to have the output directory as a base dir

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Adding level adds a good bit of scope because then one would need to decide what to log at each level. I think for now, to keep it simple, it should just be verbose (development logs) and not verbose (CI output).

The default directory is ./simulation_plan_logs right now to make sure the output does not get included in git commits. This directory is included in .gitignore to help developers keep commits clean of any accidents. We could change it to the base directory, but then we need to update .gitignore as well.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Our development logs are too informative so it might be hard to read, could have been better to have at least the level to let developers run with info or warn to get minimal output.

Regarding the the output, if we only enable to print logs to file system, it would be hard to understand issues in CI.
By printing to stdout we able to run anywhere while still being able to read the logs

simulate = flag.Bool("simulate", false, "run simulation")
serveCharts = flag.Bool("charts", false, "create and serve charts")
profiler = flag.Bool("pprof", false, "run pprof server on startup")
Expand Down Expand Up @@ -53,7 +54,7 @@ func main() {
}

// ----- setup simulation output directory and file handles
outputs, err := run.SetupOutput(*outputDirectory, *simulate, plan)
outputs, err := run.SetupOutput(*outputDirectory, *simulate, *verbose, plan)
if err != nil {
procLog.Printf("failed to setup output directory: %s", err)
os.Exit(1)
Expand Down
2 changes: 0 additions & 2 deletions tools/simulator/node/stats.go
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,6 @@ func newUpkeepStatsBuilder(
checks map[string][]string,
encoder ocr2keepers.Encoder,
) (*upkeepStatsBuilder, error) {

// count the number of transmits per account
accTr := make(map[string]int)

Expand Down Expand Up @@ -85,7 +84,6 @@ func (b *upkeepStatsBuilder) UpkeepIDs() []string {
srcUpkeepID := ocr2keepers.UpkeepIdentifier(upkeep.UpkeepID)

for _, upkeepID := range allIDs {

if upkeepID == srcUpkeepID.String() {
found = true
}
Expand Down
20 changes: 16 additions & 4 deletions tools/simulator/run/output.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ package run
import (
"errors"
"fmt"
"io"
"io/fs"
"log"
"os"
Expand All @@ -29,7 +30,18 @@ func (out *Outputs) Close() error {
return err
}

func SetupOutput(path string, simulate bool, plan config.SimulationPlan) (*Outputs, error) {
func SetupOutput(path string, simulate, verbose bool, plan config.SimulationPlan) (*Outputs, error) {
if !verbose {
logger := log.New(io.Discard, "", 0)

return &Outputs{
SimulationLog: logger,
RPCCollector: telemetry.NewNodeRPCCollector("", false),
LogCollector: telemetry.NewNodeLogCollector("", false),
EventCollector: telemetry.NewContractEventCollector(logger),
}, nil
}

var (
logger *log.Logger
lggF *os.File
Expand Down Expand Up @@ -59,9 +71,9 @@ func SetupOutput(path string, simulate bool, plan config.SimulationPlan) (*Outpu

return &Outputs{
SimulationLog: logger,
RPCCollector: telemetry.NewNodeRPCCollector(path),
LogCollector: telemetry.NewNodeLogCollector(path),
EventCollector: telemetry.NewContractEventCollector(path, logger),
RPCCollector: telemetry.NewNodeRPCCollector(path, true),
LogCollector: telemetry.NewNodeLogCollector(path, true),
EventCollector: telemetry.NewContractEventCollector(logger),
simulationLogFileHandle: lggF,
}, nil
}
Expand Down
10 changes: 3 additions & 7 deletions tools/simulator/telemetry/contract.go
Original file line number Diff line number Diff line change
Expand Up @@ -13,24 +13,20 @@ type ContractEventCollector struct {
// dependencies
logger *log.Logger

// configuration
filePath string

// internal state properties
mu sync.RWMutex
nodes map[string]*WrappedContractCollector
}

func NewContractEventCollector(path string, logger *log.Logger) *ContractEventCollector {
func NewContractEventCollector(logger *log.Logger) *ContractEventCollector {
return &ContractEventCollector{
baseCollector: baseCollector{
t: NodeLogType,
io: []io.WriteCloser{},
ioLookup: make(map[string]int),
},
logger: log.New(logger.Writer(), "[contract-event-collector]", log.Ldate|log.Ltime|log.Lshortfile),
filePath: path,
nodes: make(map[string]*WrappedContractCollector),
logger: log.New(logger.Writer(), "[contract-event-collector]", log.Ldate|log.Ltime|log.Lshortfile),
nodes: make(map[string]*WrappedContractCollector),
}
}

Expand Down
63 changes: 43 additions & 20 deletions tools/simulator/telemetry/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -10,12 +10,14 @@ import (
type NodeLogCollector struct {
baseCollector
filePath string
verbose bool
}

func NewNodeLogCollector(path string) *NodeLogCollector {
err := os.MkdirAll(path, 0750)
if err != nil && !os.IsExist(err) {
panic(err)
func NewNodeLogCollector(path string, verbose bool) *NodeLogCollector {
if verbose {
if err := os.MkdirAll(path, 0750); err != nil && !os.IsExist(err) {
panic(err)
}
}

return &NodeLogCollector{
Expand All @@ -25,6 +27,7 @@ func NewNodeLogCollector(path string) *NodeLogCollector {
ioLookup: make(map[string]int),
},
filePath: path,
verbose: verbose,
}
}

Expand Down Expand Up @@ -52,35 +55,55 @@ func (c *NodeLogCollector) GeneralLog(node string) io.Writer {

func (c *NodeLogCollector) AddNode(node string) error {
path := fmt.Sprintf("%s/%s", c.filePath, node)
err := os.MkdirAll(path, 0750)
if err != nil && !os.IsExist(err) {
panic(err)
}

var perms fs.FileMode = 0666
flag := os.O_RDWR | os.O_CREATE | os.O_TRUNC
if c.verbose {
if err := os.MkdirAll(path, 0750); err != nil && !os.IsExist(err) {
panic(err)
}
}

key := fmt.Sprintf("general/%s", node)
if err := c.addWriterForKey(fmt.Sprintf("%s/general.log", path), fmt.Sprintf("general/%s", node)); err != nil {
return err
}

f, err := os.OpenFile(fmt.Sprintf("%s/general.log", path), flag, perms)
if err != nil {
f.Close()
if err := c.addWriterForKey(fmt.Sprintf("%s/contract.log", path), fmt.Sprintf("contract/%s", node)); err != nil {
return err
}

c.ioLookup[key] = len(c.io)
c.io = append(c.io, f)
return nil
}

func (c *NodeLogCollector) addWriterForKey(path, key string) error {
if !c.verbose {
c.ioLookup[key] = len(c.io)
c.io = append(c.io, writeCloseDiscard{})

key = fmt.Sprintf("contract/%s", node)
return nil
}

var perms fs.FileMode = 0666

cLog, err := os.OpenFile(fmt.Sprintf("%s/contract.log", path), flag, perms)
flag := os.O_RDWR | os.O_CREATE | os.O_TRUNC

file, err := os.OpenFile(fmt.Sprintf("%s/general.log", path), flag, perms)
if err != nil {
cLog.Close()
file.Close()

return err
}

c.ioLookup[key] = len(c.io)
c.io = append(c.io, cLog)
c.io = append(c.io, file)

return nil
}

type writeCloseDiscard struct{}

func (writeCloseDiscard) Write(bts []byte) (int, error) {
return len(bts), nil
}

func (writeCloseDiscard) Close() error {
return nil
}
12 changes: 11 additions & 1 deletion tools/simulator/telemetry/rpc.go
Original file line number Diff line number Diff line change
Expand Up @@ -20,14 +20,16 @@ import (
type RPCCollector struct {
baseCollector
filePath string
verbose bool
nodes map[string]*WrappedRPCCollector
}

func NewNodeRPCCollector(path string) *RPCCollector {
func NewNodeRPCCollector(path string, verbose bool) *RPCCollector {
return &RPCCollector{
baseCollector: baseCollector{
t: RPCType,
},
verbose: verbose,
filePath: path,
nodes: make(map[string]*WrappedRPCCollector),
}
Expand All @@ -45,6 +47,10 @@ func (c *RPCCollector) AddNode(node string) error {
}

func (c *RPCCollector) WriteResults() error {
if !c.verbose {
return nil
}

for key, node := range c.nodes {
path := fmt.Sprintf("%s/%s", c.filePath, key)
err := os.MkdirAll(path, 0750)
Expand Down Expand Up @@ -159,6 +165,10 @@ func (c *RPCCollector) collectDataFromFile() ([]string, map[string][]rpcDataPoin
rateData := make(map[string][]rpcDataPoint)
path := c.filePath

if !c.verbose {
return ids, rateData, fmt.Errorf("verbose logging not activated")
}

files, err := os.ReadDir(path)
if err != nil {
return ids, rateData, err
Expand Down