Causeway Platform Developer

From Erights

(Difference between revisions)
Jump to: navigation, search
(Instrumenting a Platform to Generate Causeway Trace Logs)
(Instrumenting a Platform to Generate Causeway Trace Logs)
 
(3 intermediate revisions not shown)
Line 1: Line 1:
== Instrumenting a Platform to Generate Causeway Trace Logs ==
== Instrumenting a Platform to Generate Causeway Trace Logs ==
-
See [[Causeway]] for user documentation, which includes instructions for launching Causeway from a command line shell.
+
Causeway supports debugging distributed programs built on the communicating event loops concurrency model. This document describes Causeway's language-neutral trace log format and explains how to instrument a platform to generate trace logs. For concreteness, we show the trace log records generated for a simple distributed program. We discuss three different versions of the purchase-order example program, starting with the simplest implementation: Simple Ajax-style (below). If your platform supports promises, continue with [[Causeway Platform Developer: Ajax|Ajax with promotion]] and [[Causeway Platform Developer: Promises|full promises]].
 +
 
 +
=== Getting Started ===
 +
 
 +
* See [[Causeway]] for user documentation, which includes instructions for launching Causeway from a command line shell.
 +
 
 +
* Enable Causeway's debug view. Setting Causeway's debug flag enables a debug view. As events are selected in the viewer, the debug view shows the corresponding trace record from the log file. This is a very useful option, especially in the beginning, when things aren't quite working.  
-
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.
 
<pre>
<pre>
$ rune -Dcauseway_debug=true causeway.e-swt  
$ rune -Dcauseway_debug=true causeway.e-swt  
</pre>
</pre>
 +
('''Note:''' When this debug option is set, Causeway's JSON parser uses <tt>getTwine()</tt>. This is an inefficient algorithm which is not likely to change anytime soon. The trace logs for the example programs are roughly 20K; the poor performance is noticed with logs > 250K.)
 +
 +
* Open the purchase-order example program in the Causeway viewer. The examples, under the Help menu, are written for the AmbientTalk and Waterken platforms and they implement different message-passing styles. Select Help >> Open Waterken Example (Simple Ajax-style).
 +
 +
('''Note:''' Starting with one-way asynchronous messages, two patterns for handling responses are ''continuation-passing'' and ''promises''. In continuation-passing a request carries a callback argument to which a response should be sent.
 +
We refer to this as ''Ajax-style'' messaging, as it is the dominant pattern for web application development. A promise (''future'', in AmbientTalk) is a place-holder for the answer to a query; when the answer becomes available the promise resolves to that value.)
-
[[Image:debug-view.png]]
+
* Read the source code. It's part of the E distribution and can be found here.
 +
    <code>e/src/esrc/scripts/test/causeway/waterken/sources</code>
 +
    <code>e/src/esrc/scripts/test/causeway/ambientTalk/sources</code>
-
Individual tree items 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.
+
The purchase-order example program implements a procedure for handling new purchase orders. Before an order is placed, certain conditions must be met: the item is in stock and available, the customer’s account is in good standing, and the delivery options are up to date. An object residing in the "buyer" process (or vat) has remote references to objects residing in the "product" and "accounts" vats. The buyer queries the remote objects with asynchronous (non-blocking) message sends. The answers from the asynchronous inquiries must be collected and examined. The order is placed only if all requirements are satisfied.
-
# The <tt>text</tt> field string. This field is required for <tt>Comment</tt> records; it is optional for <tt>Sent</tt>, <tt>SentIf</tt>, and <tt>Resolved</tt> records. (e.g. # Order placed for West Coast Buyers)
+
If instrumenting a platform, your first test case should be the purchase-order example, ported to run on your platform. Start with Ajax-style using callbacks. This approach is less expressive than promises, but generating the trace log is more straightforward.
-
# 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. <code>_._(inventory).partInStock(partNo, teller);</code>)
+
-
# If there's no span, source file name and function name specified in the top stack entry. (e.g. <code>[buyer, 8] AsyncAnd.run</code>)
+
-
# If nothing else, a Causeway comment. (e.g. <code>## unknown sender</code>)
+
== Causeway's Trace Log Format ==
== Causeway's Trace Log Format ==
-
Causeway supports the defined by Tyler Close.  
+
Causeway supports the trace log format defined by Tyler Close at waterken.sourceforge.net/debug/.  
-
[[Image:event-types.png|alt=Trace log event types]]
+
The simple Ajax-style example logs the event types indicated by the colored boxes.
 +
 
 +
 
 +
[[Image:simple-event-types.png|alt=Simple event types]]
Line 34: Line 47:
|-
|-
| A message delivery, starting a new turn || Got
| 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
| Programmer logs a comment || Comment
|}
|}
 +
=== Logging Ajax-style Messaging in Waterken ===
=== Logging Ajax-style Messaging in Waterken ===
-
Consider the sequence of events shown below.
+
The code snippet below shows the 3 queries being fired off. All 3 answers must be examined before the order is placed. Collecting the answers is handled by an <tt>AsyncAnd</tt> object. To collect the three answers, <tt>teller</tt> is passed as an argument to each of the remote queries, serving as a callback function.
 +
 
 +
<pre>
 +
    Callback teller = new AsyncAnd(_, 3, checkAnswers(_, inventory));
 +
 
 +
    _._(inventory).partInStock(partNo, teller);
 +
    _._(creditBureau).checkCredit(name, teller);
 +
    _._(shipper).canDeliver(profile, teller);
 +
</pre>
 +
 
 +
 
 +
Consider the sequence of events from the message-order view shown below.
[[Image:part-in-stock.png|alt=Ajax-style message send]]
[[Image:part-in-stock.png|alt=Ajax-style message send]]
-
* a remote inventory object is queried for the availability of a part
+
# a remote inventory object is queried for the availability of a part
-
* the inventory object reports true to <code>teller</code>, a callback object
+
# the inventory object reports true to <tt>teller</tt>, a callback object
-
 
+
The eventual send to the inventory object has two log entries: a <tt>Sent</tt> and its corresponding <tt>Got</tt>.
The eventual send to the inventory object has two log entries: a <tt>Sent</tt> and its corresponding <tt>Got</tt>.
 +
 +
: In the <tt>Sent</tt> trace record:
 +
:: <tt>anchor</tt> uniquely identifies the origin of this message send as the 2nd messaging event from the buyer vat, turn 3.
 +
:: <tt>message</tt> is a generated string which uniquely identifies a message.
 +
:: <tt>trace</tt> is the stack capture at the point of the message send.
 +
 +
: The corresponding <tt>Got</tt> has a matching <tt>message</tt>. 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 yet supported.
 +
 +
('''Note:''' The <tt>loop</tt> field identifies the vat by a unique string. By convention, Causeway picks up the part following "/-/", in this case buyer, for a short display name.)
 +
 +
('''Note:''' The <tt>timestamp</tt> field is optional. Currently, Causeway ignores it, so it's not shown in the remaining trace records.)
<pre>
<pre>
     "class" : [ "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
     "class" : [ "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
     "anchor" : {
     "anchor" : {
-
       "number" : 3,
+
       "number" : 2,
       "turn" : {
       "turn" : {
         "loop" : "http://localhost:8080/-/buyer/",
         "loop" : "http://localhost:8080/-/buyer/",
Line 68: Line 95:
       }
       }
     },
     },
-
     "message" : "lqhjpwbbeemozk-2-0",
+
     "message" : "qvet6lrs4zsfpv-2-0",
-
     "timestamp" : 1274238401772,
+
     "timestamp" : 1275338022120,
     "trace" : {
     "trace" : {
       "calls" : [ {
       "calls" : [ {
           "name" : "Main.Buy.fulfill",
           "name" : "Main.Buy.fulfill",
-
           "source" : "org/waterken/purchase_ajax/Main.java",
+
           "source" : "org/waterken/simple_purchase_ajax/Main.java",
           "span" : [ [ 68 ] ]
           "span" : [ [ 68 ] ]
         }, {
         }, {
           "name" : "Main.Buy.fulfill",
           "name" : "Main.Buy.fulfill",
-
           "source" : "org/waterken/purchase_ajax/Main.java",
+
           "source" : "org/waterken/simple_purchase_ajax/Main.java",
           "span" : [ [ 48 ] ]
           "span" : [ [ 48 ] ]
         } ]
         } ]
     }
     }
</pre>
</pre>
-
 
-
The <tt>anchor</tt> uniquely identifies the origin of this message send as the 3rd messaging event from the buyer vat, turn 3.
 
-
 
-
The <tt>message</tt> is a generated string which uniquely identifies a message.
 
-
 
-
The <tt>trace</tt> is the stack capture at the point of the message send.
 
-
 
-
Note: The <tt>loop</tt> 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 <tt>timestamp</tt> field is optional. Currently, it is ignored by Causeway, so it's not shown in the remaining trace records.
 
<pre>
<pre>
Line 102: Line 119:
       }
       }
     },
     },
-
     "message" : "lqhjpwbbeemozk-2-0",
+
     "message" : "qvet6lrs4zsfpv-2-0",
 +
    "timestamp" : 1275338022291,
     "trace" : {
     "trace" : {
       "calls" : [ {
       "calls" : [ {
           "name" : "InventoryMaker.InventoryX.partInStock",
           "name" : "InventoryMaker.InventoryX.partInStock",
-
           "source" : "org/waterken/purchase_ajax/InventoryMaker.java"
+
           "source" : "org/waterken/simple_purchase_ajax/InventoryMaker.java"
         } ]
         } ]
     }
     }
</pre>
</pre>
-
 
-
The corresponding <tt>Got</tt> record matches on <tt>message</tt>. 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 <tt>teller</tt> has two log entries: a <tt>Sent</tt> and its corresponding <tt>Got</tt>.
Reporting true to <tt>teller</tt> has two log entries: a <tt>Sent</tt> and its corresponding <tt>Got</tt>.
 +
 +
: The reply to the query is the 2nd messaging event from the product vat, turn 2.
 +
 +
: The corresponding <tt>Got</tt> has a matching <tt>message</tt>. The message delivery in the buyer vat starts a new turn, turn 10.
<pre>
<pre>
Line 125: Line 144:
       }
       }
     },
     },
-
     "message" : "ewrigzpctikrhk-1-0",
+
     "message" : "4qjohg533s6cjn-1-0",
     "trace" : {
     "trace" : {
       "calls" : [ {
       "calls" : [ {
           "name" : "InventoryMaker.InventoryX.partInStock",
           "name" : "InventoryMaker.InventoryX.partInStock",
-
           "source" : "org/waterken/purchase_ajax/InventoryMaker.java",
+
           "source" : "org/waterken/simple_purchase_ajax/InventoryMaker.java",
           "span" : [ [ 19 ] ]
           "span" : [ [ 19 ] ]
         } ]
         } ]
     }
     }
</pre>
</pre>
-
 
-
The <tt>anchor</tt> uniquely identifies the origin of this message send as the 2nd messaging event from the product vat, turn 2.
 
<pre>
<pre>
Line 146: Line 163:
       }
       }
     },
     },
-
     "message" : "ewrigzpctikrhk-1-0",
+
     "message" : "4qjohg533s6cjn-1-0",
     "trace" : {
     "trace" : {
       "calls" : [ {
       "calls" : [ {
           "name" : "AsyncAnd.run",
           "name" : "AsyncAnd.run",
-
           "source" : "org/waterken/purchase_ajax/AsyncAnd.java"
+
           "source" : "org/waterken/simple_purchase_ajax/AsyncAnd.java"
         } ]
         } ]
     }
     }
</pre>
</pre>
-
The corresponding <tt>Got</tt> record matches on <tt>message</tt>. The message delivery in the buyer vat starts a new turn, turn 10.
+
In the Causeway viewer, individual tree items represent events and their descriptive labels depend on the information available in the logged record for the event. To present the most useful information available, Causeway labels tree items according to the following priority.
-
 
+
-
=== Logging Promise-based Messaging in Waterken ===
+
-
 
+
-
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.
+
-
 
+
-
 
+
-
<pre>
+
-
  "class" : [ "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 1,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/",
+
-
        "number" : 2
+
-
      }
+
-
    },
+
-
    "message" : "3t4ubiwssjzuy2-2-0",
+
-
    "trace" : {
+
-
      "calls" : [ {
+
-
          "name" : "Buyer.Buy.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/Buyer.java",
+
-
          "span" : [ [ 39 ] ]
+
-
        }, {
+
-
          "name" : "Buyer.Buy.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/Buyer.java",
+
-
          "span" : [ [ 24 ] ]
+
-
        } ]
+
-
    }
+
-
</pre>
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 0,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/product/",
+
-
        "number" : 1
+
-
      }
+
-
    },
+
-
    "message" : "3t4ubiwssjzuy2-2-0",
+
-
    "trace" : {
+
-
      "calls" : [ {
+
-
          "name" : "InventoryMaker.InventoryX.partInStock",
+
-
          "source" : "org/waterken/purchase_promise/InventoryMaker.java"
+
-
        } ]
+
-
    }
+
-
</pre>
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.Returned", "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 1,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/product/",
+
-
        "number" : 1
+
-
      }
+
-
    },
+
-
    "message" : "3t4ubiwssjzuy2-2-0-return"
+
-
</pre>
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 0,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/",
+
-
        "number" : 5
+
-
      }
+
-
    },
+
-
    "message" : "3t4ubiwssjzuy2-2-0-return"
+
-
</pre>
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.Fulfilled", "org.ref_send.log.Resolved", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 1,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/",
+
-
        "number" : 5
+
-
      }
+
-
    },
+
-
    "condition" : "http://localhost:8080/-/buyer/#p3"
+
-
</pre>
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 0,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/",
+
-
        "number" : 8
+
-
      }
+
-
    },
+
-
    "message" : "http://localhost:8080/-/buyer/#w3",
+
-
    "trace" : {
+
-
      "calls" : [ {
+
-
          "name" : "AsyncAnd.DoAnswer.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/AsyncAnd.java"
+
-
        } ]
+
-
    }
+
-
</pre>
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.Progressed", "org.ref_send.log.Resolved", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 1,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/",
+
-
        "number" : 8
+
-
      }
+
-
    },
+
-
    "condition" : "http://localhost:8080/-/buyer/#p6",
+
-
    "trace" : {
+
-
      "calls" : [ {
+
-
          "name" : "AsyncAnd.DoAnswer.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/AsyncAnd.java",
+
-
          "span" : [ [ 34 ] ]
+
-
        }, {
+
-
          "name" : "AsyncAnd.DoAnswer.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/AsyncAnd.java",
+
-
          "span" : [ [ 16 ] ]
+
-
        } ]
+
-
    }
+
-
</pre>
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 0,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/",
+
-
        "number" : 14
+
-
      }
+
-
    },
+
-
    "message" : "http://localhost:8080/-/buyer/#w6",
+
-
    "trace" : {
+
-
      "calls" : [ {
+
-
          "name" : "Buyer.CheckAnswers.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/Buyer.java"
+
-
        } ]
+
-
    }
+
-
</pre>
+
-
 
+
-
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.
+
-
 
+
-
 
+
-
[[Image:buyer-po-view.png|alt=Buyer events in process order]]
+
-
 
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.SentIf", "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 7,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/",
+
-
        "number" : 2
+
-
      }
+
-
    },
+
-
    "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" : [ [ 46 ] ]
+
-
        }, {
+
-
          "name" : "Buyer.Buy.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/Buyer.java",
+
-
          "span" : [ [ 24 ] ]
+
-
        } ]
+
-
    }
+
-
</pre>
+
-
 
+
-
<pre>
+
-
    "class" : [ "org.ref_send.log.SentIf", "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
+
-
    "anchor" : {
+
-
      "number" : 4,
+
-
      "turn" : {
+
-
        "loop" : "http://localhost:8080/-/buyer/",
+
-
        "number" : 2
+
-
      }
+
-
    },
+
-
    "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" : [ [ 60 ] ]
+
-
        }, {
+
-
          "name" : "Buyer.Buy.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/Buyer.java",
+
-
          "span" : [ [ 43 ] ]
+
-
        }, {
+
-
          "name" : "Buyer.Buy.fulfill",
+
-
          "source" : "org/waterken/purchase_promise/Buyer.java",
+
-
          "span" : [ [ 24 ] ]
+
-
        } ]
+
-
    }
+
-
</pre>
+
-
 
+
-
 
+
-
=== 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.
+
# User comments specified in the <tt>text</tt> field, prefixed with "#".
 +
# Source code specified in the top call stack object. The <tt>trace</tt> object must include a <tt>span</tt>.
 +
# Source file and function name specified in top call stack object. The <tt>trace</tt> object must include a <tt>name</tt> and <tt>source</tt>.
 +
# If none of the above, the label is a Causeway-generated comment, prefixed with "##", e.g., ## unknown sender.
-
Waterken guarantees message order delivery and 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.)
+
The resulting process-order view and message-order view are shown below.  
-
Note: Resending a message after a connection is re-established can result in 2 identical <tt>Sent</tt> events being logged. Causeway notices when the event records are identical and ignores the duplicate.
+
[[Image:simple-pov-mov.png|alt=Simple process-order view and message-order view]]
[[Category:Applications]]
[[Category:Applications]]

Latest revision as of 23:48, 16 June 2010

Contents

Instrumenting a Platform to Generate Causeway Trace Logs

Causeway supports debugging distributed programs built on the communicating event loops concurrency model. This document describes Causeway's language-neutral trace log format and explains how to instrument a platform to generate trace logs. For concreteness, we show the trace log records generated for a simple distributed program. We discuss three different versions of the purchase-order example program, starting with the simplest implementation: Simple Ajax-style (below). If your platform supports promises, continue with Ajax with promotion and full promises.

Getting Started

  • See Causeway for user documentation, which includes instructions for launching Causeway from a command line shell.
  • Enable Causeway's debug view. Setting Causeway's debug flag enables a debug view. As events are selected in the viewer, the debug view shows the corresponding trace record from the log file. This is a very useful option, especially in the beginning, when things aren't quite working.
$ rune -Dcauseway_debug=true causeway.e-swt 

(Note: When this debug option is set, Causeway's JSON parser uses getTwine(). This is an inefficient algorithm which is not likely to change anytime soon. The trace logs for the example programs are roughly 20K; the poor performance is noticed with logs > 250K.)

  • Open the purchase-order example program in the Causeway viewer. The examples, under the Help menu, are written for the AmbientTalk and Waterken platforms and they implement different message-passing styles. Select Help >> Open Waterken Example (Simple Ajax-style).

(Note: Starting with one-way asynchronous messages, two patterns for handling responses are continuation-passing and promises. In continuation-passing a request carries a callback argument to which a response should be sent. We refer to this as Ajax-style messaging, as it is the dominant pattern for web application development. A promise (future, in AmbientTalk) is a place-holder for the answer to a query; when the answer becomes available the promise resolves to that value.)

  • Read the source code. It's part of the E distribution and can be found here.
   e/src/esrc/scripts/test/causeway/waterken/sources
   e/src/esrc/scripts/test/causeway/ambientTalk/sources

The purchase-order example program implements a procedure for handling new purchase orders. Before an order is placed, certain conditions must be met: the item is in stock and available, the customer’s account is in good standing, and the delivery options are up to date. An object residing in the "buyer" process (or vat) has remote references to objects residing in the "product" and "accounts" vats. The buyer queries the remote objects with asynchronous (non-blocking) message sends. The answers from the asynchronous inquiries must be collected and examined. The order is placed only if all requirements are satisfied.

If instrumenting a platform, your first test case should be the purchase-order example, ported to run on your platform. Start with Ajax-style using callbacks. This approach is less expressive than promises, but generating the trace log is more straightforward.

Causeway's Trace Log Format

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

The simple Ajax-style example logs the event types indicated by the colored boxes.


Simple 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
Programmer logs a comment Comment


Logging Ajax-style Messaging in Waterken

The code snippet below shows the 3 queries being fired off. All 3 answers must be examined before the order is placed. Collecting the answers is handled by an AsyncAnd object. To collect the three answers, teller is passed as an argument to each of the remote queries, serving as a callback function.

    Callback teller = new AsyncAnd(_, 3, checkAnswers(_, inventory));

    _._(inventory).partInStock(partNo, teller);
    _._(creditBureau).checkCredit(name, teller);
    _._(shipper).canDeliver(profile, teller);


Consider the sequence of events from the message-order view shown below.

Ajax-style message send

  1. a remote inventory object is queried for the availability of a part
  2. 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.

In the Sent trace record:
anchor uniquely identifies the origin of this message send as the 2nd messaging event from the buyer vat, turn 3.
message is a generated string which uniquely identifies a message.
trace is the stack capture at the point of the message send.
The corresponding Got has a matching 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 yet supported.

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

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

    "class" : [ "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 2,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 3
      }
    },
    "message" : "qvet6lrs4zsfpv-2-0",
    "timestamp" : 1275338022120,
    "trace" : {
      "calls" : [ {
          "name" : "Main.Buy.fulfill",
          "source" : "org/waterken/simple_purchase_ajax/Main.java",
          "span" : [ [ 68 ] ]
        }, {
          "name" : "Main.Buy.fulfill",
          "source" : "org/waterken/simple_purchase_ajax/Main.java",
          "span" : [ [ 48 ] ]
        } ]
    }
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 1,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/product/",
        "number" : 2
      }
    },
    "message" : "qvet6lrs4zsfpv-2-0",
    "timestamp" : 1275338022291,
    "trace" : {
      "calls" : [ {
          "name" : "InventoryMaker.InventoryX.partInStock",
          "source" : "org/waterken/simple_purchase_ajax/InventoryMaker.java"
        } ]
    }

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

The reply to the query is the 2nd messaging event from the product vat, turn 2.
The corresponding Got has a matching message. The message delivery in the buyer vat starts a new turn, turn 10.
    "class" : [ "org.ref_send.log.Sent", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 2,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/product/",
        "number" : 2
      }
    },
    "message" : "4qjohg533s6cjn-1-0",
    "trace" : {
      "calls" : [ {
          "name" : "InventoryMaker.InventoryX.partInStock",
          "source" : "org/waterken/simple_purchase_ajax/InventoryMaker.java",
          "span" : [ [ 19 ] ]
        } ]
    }
    "class" : [ "org.ref_send.log.Got", "org.ref_send.log.Event" ],
    "anchor" : {
      "number" : 1,
      "turn" : {
        "loop" : "http://localhost:8080/-/buyer/",
        "number" : 10
      }
    },
    "message" : "4qjohg533s6cjn-1-0",
    "trace" : {
      "calls" : [ {
          "name" : "AsyncAnd.run",
          "source" : "org/waterken/simple_purchase_ajax/AsyncAnd.java"
        } ]
    }

In the Causeway viewer, individual tree items represent events and their descriptive labels depend on the information available in the logged record for the event. To present the most useful information available, Causeway labels tree items according to the following priority.

  1. User comments specified in the text field, prefixed with "#".
  2. Source code specified in the top call stack object. The trace object must include a span.
  3. Source file and function name specified in top call stack object. The trace object must include a name and source.
  4. If none of the above, the label is a Causeway-generated comment, prefixed with "##", e.g., ## unknown sender.


The resulting process-order view and message-order view are shown below.

Simple process-order view and message-order view

Personal tools
more tools