Causeway Platform Developer

From Erights

(Difference between revisions)
Jump to: navigation, search
(Logging Promise-based Messaging in Waterken)
(Logging Promise-based Messaging in Waterken)
Line 161: Line 161:
(Note: This section on promises is incomplete and will be updated soon. tstanley 5/24/10)
(Note: This section on promises is incomplete and will be updated soon. tstanley 5/24/10)
-
Consider the sequence of events shown below.
+
<pre>
 +
    Promise<Boolean> partP = _._(inventory).partInStock(partNo);
 +
    Promise<Boolean> creditP = _._(creditBureau).checkCredit(name);
 +
    Promise<Boolean> deliverP = _._(shipper).canDeliver(profile);
-
[[Image:promise-part-in-stock.png|alt=Promise-based message send]]
+
    final Promise<Boolean> allOkP =
 +
        new AsyncAnd(_).run(partP, creditP, deliverP);
 +
    /*
 +
    * Register a when-block on promise returned by AsyncAnd.
 +
    * The block executes when the promise resolves (either
 +
    * fulfilled or rejected).
 +
    */
-
Note: For the purpose of describing the trace records the screenshot shows events that actually will be filtered by Causeway and do not appear in the message-order view.
+
    _.when(allOkP, checkAnswers(_, inventory));
 +
</pre>
 +
<pre>
 +
    public Promise<Boolean> run(Promise<Boolean>... answers) {
 +
        final Channel<Boolean> result = _.defer();
 +
        final int[] expected = {answers.length};
 +
        for (Promise<Boolean> answerP : answers) {
-
[[Image:wk-promise-messaging.png|alt=Waterken promise messaging]]
+
            /*
 +
            * Register a when-block on each promise. The block executes
 +
            * when the promise resolves (either fulfilled or rejected).
 +
            */
 +
            _.when(answerP, new DoAnswer(expected, result.resolver));
 +
        }
 +
        return result.promise;
 +
    }
 +
</pre>
 +
 +
We start with a detailed description of a single message, <code>partInStock</code>. Then we'll look at how <code>AsyncAnd</code> collects the answers and reports a final result.
 +
 +
* The graph structure representing the message send and resolution
 +
* The events logged
 +
* The graph filter
 +
 +
 +
 +
[[Image:raw-d1-d2.png|alt=foo]]
 +
 +
<pre>
 +
    public Void fulfill(Boolean answer) {
 +
        if (answer) {
 +
            myExpected[0]--;
 +
            if (myExpected[0] == 0) {
 +
                /*
 +
                * Resolve the promise with true.
 +
                */
 +
                myResolver.apply(true);
 +
            } else {
 +
                /*
 +
                * Progress had been made in resolving the promise.
 +
                * If logging is on, a Progressed event record is written.
 +
                * If logging is off, this is a noop.
 +
                */
 +
                myResolver.progress();
 +
            }
 +
        } else {
 +
            /*
 +
            * Resolve the promise with false. Notice that this
 +
            * short-circuits the logic: any remaining expected answers
 +
            * are ignored.
 +
            */
 +
            myResolver.apply(false);
 +
        }
 +
    }
 +
</pre>
<pre>
<pre>
Line 307: Line 368:
     }
     }
</pre>
</pre>
 +
 +
Consider the sequence of events shown below.
 +
 +
 +
[[Image:promise-part-in-stock.png|alt=Promise-based message send]]
 +
 +
 +
Note: For the purpose of describing the trace records the screenshot shows events that actually will be filtered by Causeway and do not appear in the message-order view.
The registration of when-blocks, logged as <tt>SentIf</tt> records, are filtered from the message-order view, as they don't contribute to the understanding of message flow. However, they do appear in process-order, as shown below.
The registration of when-blocks, logged as <tt>SentIf</tt> records, are filtered from the message-order view, as they don't contribute to the understanding of message flow. However, they do appear in process-order, as shown below.

Revision as of 00:50, 29 May 2010

Contents

Instrumenting a Platform to Generate Causeway Trace Logs

See Causeway for user documentation, which includes instructions for launching Causeway from a command line shell.

Setting Causeway's debug flag enables a Debug view. As events are selected in the viewer, the Debug view shows the corresponding trace record in the log file.

$ rune -Dcauseway_debug=true causeway.e-swt 


Image:debug-view.png


Individual tree items (e.g. shown in the Message-order view above) represent events and their descriptive labels depend on the information available in the trace record for the event. Causeway labels the tree items according to the following priority.

  1. The text field string. This field is required for Comment records; it is optional for Sent, SentIf, and Resolved records. (e.g. # Order placed for West Coast Buyers)
  2. If the trace record has at least one stack entry with a source and span, a single line of source code from the source file specified in the top stack entry. (e.g. _._(inventory).partInStock(partNo, teller);)
  3. If there's no span, source file name and function name specified in the top stack entry. (e.g. [buyer, 8] AsyncAnd.run)
  4. If nothing else, a Causeway comment. (e.g. ## unknown sender)

Causeway's Trace Log Format

Causeway supports the trace log format defined by Tyler Close at waterken.sourceforge.net/debug/.

Trace log event types


When causality tracing is on the events are logged as follows.

Event Record type
An eventual send to an object Sent
A message delivery, starting a new turn Got
Registration of a when-block, to execute when a promise resolves SentIf
Returned result from a remote object, for local promise resolution Returned
A state-based event contributes to promise resolution Progressed
A promise resolves Fulfilled or Rejected
Programmer logs a comment Comment


Logging Ajax-style Messaging in Waterken

Consider the sequence of events shown below.

Ajax-style message send

  • a remote inventory object is queried for the availability of a part
  • the inventory object reports true to teller, a callback object


The eventual send to the inventory object has two log entries: a Sent and its corresponding Got.

    "class" : [ "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 3,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 3
      }
    },
    "message" : "lqhjpwbbeemozk-2-0",
    "timestamp" : 1274238401772,
    "trace" : {
      "calls" : [ {
          "name" : "Main.Buy.fulfill",
          "source" : "org/waterken/purchase_ajax/Main.java",
          "span" : [ [ 68 ] ]
        }, {
          "name" : "Main.Buy.fulfill",
          "source" : "org/waterken/purchase_ajax/Main.java",
          "span" : [ [ 48 ] ]
        } ]
    }

The anchor uniquely identifies the origin of this message send as the 3rd messaging event from the buyer vat, turn 3.

The message is a generated string which uniquely identifies a message.

The trace is the stack capture at the point of the message send.

Note: The loop field identifies the vat by URI. By convention, Causeway picks up the part following "/-/", in this case buyer, for a short display name.

Note: The timestamp field is optional. Currently, it is ignored by Causeway, so it's not shown in the remaining trace records.

    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 1,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/product/",
        "number" : 2
      }
    },
    "message" : "lqhjpwbbeemozk-2-0",
    "trace" : {
      "calls" : [ {
          "name" : "InventoryMaker.InventoryX.partInStock",
          "source" : "org/waterken/purchase_ajax/InventoryMaker.java"
        } ]
    }

The corresponding Got record matches on message. The message delivery in the product vat starts a new turn, turn 2. Being at the top of a new turn, there is limited stack capture and getting a source span through Java reflection, is not practical.

Reporting true to teller has two log entries: a Sent and its corresponding Got.

    "class" : [ "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 2,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/product/",
        "number" : 2
      }
    },
    "message" : "ewrigzpctikrhk-1-0",
    "trace" : {
      "calls" : [ {
          "name" : "InventoryMaker.InventoryX.partInStock",
          "source" : "org/waterken/purchase_ajax/InventoryMaker.java",
          "span" : [ [ 19 ] ]
        } ]
    }

The anchor uniquely identifies the origin of this message send as the 2nd messaging event from the product vat, turn 2.

    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 1,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 10
      }
    },
    "message" : "ewrigzpctikrhk-1-0",
    "trace" : {
      "calls" : [ {
          "name" : "AsyncAnd.run",
          "source" : "org/waterken/purchase_ajax/AsyncAnd.java"
        } ]
    }

The corresponding Got record matches on message. The message delivery in the buyer vat starts a new turn, turn 10.

Logging Promise-based Messaging in Waterken

(Note: This section on promises is incomplete and will be updated soon. tstanley 5/24/10)

    Promise<Boolean> partP = _._(inventory).partInStock(partNo);
    Promise<Boolean> creditP = _._(creditBureau).checkCredit(name);
    Promise<Boolean> deliverP = _._(shipper).canDeliver(profile);

    final Promise<Boolean> allOkP = 
        new AsyncAnd(_).run(partP, creditP, deliverP);

    /*
     * Register a when-block on promise returned by AsyncAnd. 
     * The block executes when the promise resolves (either 
     * fulfilled or rejected).
     */

    _.when(allOkP, checkAnswers(_, inventory));
    public Promise<Boolean> run(Promise<Boolean>... answers) {
        final Channel<Boolean> result = _.defer();
        final int[] expected = {answers.length};
        for (Promise<Boolean> answerP : answers) {

            /*
             * Register a when-block on each promise. The block executes
             * when the promise resolves (either fulfilled or rejected).
             */

            _.when(answerP, new DoAnswer(expected, result.resolver));
        }
        return result.promise;
    }

We start with a detailed description of a single message, partInStock. Then we'll look at how AsyncAnd collects the answers and reports a final result.

  • The graph structure representing the message send and resolution
  • The events logged
  • The graph filter


foo

    public Void fulfill(Boolean answer) {
        if (answer) {
            myExpected[0]--;
            if (myExpected[0] == 0) {
                /*
                 * Resolve the promise with true.
                 */
                myResolver.apply(true);
            } else {
                /*
                 * Progress had been made in resolving the promise.
                 * If logging is on, a Progressed event record is written.
                 * If logging is off, this is a noop.
                 */
                myResolver.progress();
            }
        } else {
            /*
             * Resolve the promise with false. Notice that this 
             * short-circuits the logic: any remaining expected answers
             * are ignored.
             */
            myResolver.apply(false);
        }
    }
    "class" : [ "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 2,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 3
      }
    },
    "message" : "jisyrc633lurdq-2-0",
    "trace" : {
      "calls" : [ {
          "name" : "Buyer.Buy.fulfill",
          "source" : "org/waterken/purchase_promise/Buyer.java",
          "span" : [ [ 59 ] ]
        }, {
          "name" : "Buyer.Buy.fulfill",
          "source" : "org/waterken/purchase_promise/Buyer.java",
          "span" : [ [ 44 ] ]
        } ]
    }
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 1,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/product/",
        "number" : 2
      }
    },
    "message" : "jisyrc633lurdq-2-0",
    "trace" : {
      "calls" : [ {
          "name" : "InventoryMaker.InventoryX.partInStock",
          "source" : "org/waterken/purchase_promise/InventoryMaker.java"
        } ]
    }
    "class" : [ "org.ref_send.log.Returned", "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 2,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/product/",
        "number" : 2
      }
    },
    "message" : "jisyrc633lurdq-2-0-return",
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 1,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 6
      }
    },
    "message" : "jisyrc633lurdq-2-0-return",
    "class" : [ "org.ref_send.log.Fulfilled", "org.ref_send.log.Resolved", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 2,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 6
      }
    },
    "condition" : "http://localhost:8080/-/buyer/#p3",
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 1,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 9
      }
    },
    "message" : "http://localhost:8080/-/buyer/#w3",
    "trace" : {
      "calls" : [ {
          "name" : "AsyncAnd.DoAnswer.fulfill",
          "source" : "org/waterken/purchase_promise/AsyncAnd.java"
        } ]
    }
    "class" : [ "org.ref_send.log.Progressed", "org.ref_send.log.Resolved", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 2,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 9
      }
    },
    "condition" : "http://localhost:8080/-/buyer/#p6",
    "trace" : {
      "calls" : [ {
          "name" : "AsyncAnd.DoAnswer.fulfill",
          "source" : "org/waterken/purchase_promise/AsyncAnd.java",
          "span" : [ [ 52 ] ]
        }, {
          "name" : "AsyncAnd.DoAnswer.fulfill",
          "source" : "org/waterken/purchase_promise/AsyncAnd.java",
          "span" : [ [ 26 ] ]
        } ]
    }
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 1,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 15
      }
    },
    "message" : "http://localhost:8080/-/buyer/#w6",
    "trace" : {
      "calls" : [ {
          "name" : "Buyer.CheckAnswers.fulfill",
          "source" : "org/waterken/purchase_promise/Buyer.java"
        } ]
    }

Consider the sequence of events shown below.


Promise-based message send


Note: For the purpose of describing the trace records the screenshot shows events that actually will be filtered by Causeway and do not appear in the message-order view.

The registration of when-blocks, logged as SentIf records, are filtered from the message-order view, as they don't contribute to the understanding of message flow. However, they do appear in process-order, as shown below.


SentIf events in process-order view


    "class" : [ "org.ref_send.log.SentIf", "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 8,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 3
      }
    },
    "condition" : "http://localhost:8080/-/buyer/#p6",
    "message" : "http://localhost:8080/-/buyer/#w6",
    "trace" : {
      "calls" : [ {
          "name" : "Buyer.Buy.fulfill",
          "source" : "org/waterken/purchase_promise/Buyer.java",
          "span" : [ [ 72 ] ]
        }, {
          "name" : "Buyer.Buy.fulfill",
          "source" : "org/waterken/purchase_promise/Buyer.java",
          "span" : [ [ 44 ] ]
        } ]
    }
    "class" : [ "org.ref_send.log.SentIf", "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 5,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 3
      }
    },
    "condition" : "http://localhost:8080/-/buyer/#p3",
    "message" : "http://localhost:8080/-/buyer/#w3",
    "trace" : {
      "calls" : [ {
          "name" : "AsyncAnd.run",
          "source" : "org/waterken/purchase_promise/AsyncAnd.java",
          "span" : [ [ 87 ] ]
        }, {
          "name" : "Buyer.Buy.fulfill",
          "source" : "org/waterken/purchase_promise/Buyer.java",
          "span" : [ [ 63 ] ]
        }, {
          "name" : "Buyer.Buy.fulfill",
          "source" : "org/waterken/purchase_promise/Buyer.java",
          "span" : [ [ 44 ] ]
        } ]
    }

Performance Issues in Waterken

Due to the expense of stack capture in Java, tracing in Waterken incurs roughly, an order of magnitude performance penalty. If tracing is off, there is no penalty.

Waterken guarantees message order delivery and in addition, if a connection is dropped, there's enough information to know about partial success. For example, if 2 messages (msg1, msg2) are sent from vat A to vat B, they are guaranteed to be processed in the order sent. If the connection is dropped after msg1 is successfully sent, when the connection is re-established, it is known that only msg2 must be resent.

The identifiers used to support these guarantees are also used for tracing. The advantage of these multi-purpose identifiers is there is no overhead when tracing is off (i.e., unique message identifiers, just for tracing, are not sent out over the wire.)

Note: Resending a message after a connection is re-established can result in 2 identical Sent events being logged. Causeway notices when the event records are identical and ignores the duplicate.


Logging Ajax-style Messaging in AmbientTalk

Logging Futures-based Messaging in AmbientTalk

Performance Issues in AmbientTalk

Personal tools
more tools