lib: Print out timing from core graph generation

This should help us determine what steps need improving. As it turns
out, autoedges are approximately the slowest. (Highly dependent on the
specific mcl code being used.)

The trend is clear though; note the units:

main: new graph took: 913.653µs
main: auto edges took: 9.273807153s
main: auto grouping took: 28.690819ms
main: send/recv building took: 566ns

main: new graph took: 779.255µs
main: auto edges took: 4.03670168s
main: auto grouping took: 37.682101ms
main: send/recv building took: 121.017µs

main: new graph took: 1.157479ms
main: auto edges took: 3.794132165s
main: auto grouping took: 49.732836ms
main: send/recv building took: 95.921µs

main: new graph took: 900.937µs
main: auto edges took: 7.206085s
main: auto grouping took: 25.508671ms
main: send/recv building took: 489ns

main: new graph took: 794.224µs
main: auto edges took: 4.313729756s
main: auto grouping took: 47.970533ms
main: send/recv building took: 207.62µs

main: new graph took: 884.49µs
main: auto edges took: 7.585529786s
main: auto grouping took: 24.327938ms
main: send/recv building took: 72.741µs

main: new graph took: 774.157µs
main: auto edges took: 2.827380129s
main: auto grouping took: 28.303023ms
main: send/recv building took: 85.246µs

main: new graph took: 746.841µs
main: auto edges took: 2.775868117s
main: auto grouping took: 33.11291ms
main: send/recv building took: 104.875µs

main: new graph took: 796.445µs
main: auto edges took: 2.71556122s
main: auto grouping took: 24.03827ms
main: send/recv building took: 106.414µs

main: new graph took: 1.217452ms
main: auto edges took: 2.908416104s
main: auto grouping took: 61.175916ms
main: send/recv building took: 92.328µs

main: new graph took: 807.894µs
main: auto edges took: 3.222089261s
main: auto grouping took: 40.032629ms
main: send/recv building took: 106.49µs

main: new graph took: 986.963µs
main: auto edges took: 3.538425263s
main: auto grouping took: 30.660849ms
main: send/recv building took: 99.74µs

lib/main.go

@@ -655,13 +655,16 @@ func (obj *Main) Run() error {
 				Logf("gapi is empty!")
 				continue
 			}
+			var timing time.Time
 
 			// make the graph from yaml, lib, puppet->yaml, or dsl!
+			timing = time.Now()
 			newGraph, err := gapiImpl.Graph() // generate graph!
 			if err != nil {
 				Logf("error creating new graph: %+v", err)
 				continue
 			}
+			Logf("new graph took: %s", time.Since(timing))
 			if obj.Flags.Debug {
 				Logf("new graph: %+v", newGraph)
 			}
@@ -709,19 +712,23 @@ func (obj *Main) Run() error {
 
 			// XXX: can we change this into a ge.Apply operation?
 			// add autoedges; modifies the graph only if no error
+			timing = time.Now()
 			if err := obj.ge.AutoEdge(); err != nil {
 				obj.ge.Abort() // delete graph
 				Logf("error running auto edges: %+v", err)
 				continue
 			}
+			Logf("auto edges took: %s", time.Since(timing))
 
 			// XXX: can we change this into a ge.Apply operation?
 			// run autogroup; modifies the graph
+			timing = time.Now()
 			if err := obj.ge.AutoGroup(&autogroup.NonReachabilityGrouper{}); err != nil {
 				obj.ge.Abort() // delete graph
 				Logf("error running auto grouping: %+v", err)
 				continue
 			}
+			Logf("auto grouping took: %s", time.Since(timing))
 
 			// XXX: can we change this into a ge.Apply operation?
 			// run reversals; modifies the graph
@@ -737,6 +744,7 @@ func (obj *Main) Run() error {
 			// a resource that had previously received some data and
 			// is now different than the equivalent resource in this
 			// new incoming graph!
+			timing = time.Now()
 			if err := obj.ge.Apply(func(g *pgraph.Graph) error { // apply runs on nextGraph (new)
 				old := obj.ge.Graph()
 				if old.NumVertices() == 0 { // skip initial empty graph
@@ -800,6 +808,7 @@ func (obj *Main) Run() error {
 				Logf("error applying operation to the new graph: %+v", err)
 				continue
 			}
+			Logf("send/recv building took: %s", time.Since(timing))
 
 			// Double check before we commit.
 			if err := obj.ge.Apply(func(graph *pgraph.Graph) error {