Messaging of AliExpress

The biggest world global eCommerce - AliExpress has its own messaging and its source code looks interesting especially with claims "Throughout the period, 99.996% of the delay fell within 10ms, very few due to GC caused by the pause in 50ms or less, for the read and write ratio is almost balanced distributed message engine, the results are all exciting." which are about Java software.
With first look following can be spotted: heavy usage of java.util.concurrent, volatile keyword, ByteBuffers and very limited usage of synchronized blocks. File storage uses plain RandomAccessFile with OS-mapped ByteBuffers where everything read and written is with computed offsets. Flushing data to disk is performed in file groups which is very wise due to mechanical sympathy with underlying disks (think about hardware I/O queues and servicing according to given offsets). Memory storage uses direct ByteBuffers not affected by GC and also locked into physical memory with POSIX mlock call. Very smart! I was exploiting the last feature while writing near RealTime software for T-Mobile emergency number. It really helps to achieve low latency without outliers.

Dlaczego nie należy kupować Toyoty starszej niż 2011

https://hownot2code.com/2016/10/18/toyota-81-514-issues-in-the-code/
https://en.wikipedia.org/wiki/Sudden_unintended_acceleration

Sprytne zegarki

Standardy wyznacza Android Wear i względem tego najdroższego segmentu (powyżej 500 zł) mamy dwa inne - rozwiązania bazujące na gotowych układach System on a Chip, do których trzeba (w uproszczeniu) dołożyć wyświetlacz, baterię i pasek; oryginalne projekty zrobione od podstaw w oparciu o podzespoły dostępne na rynku, bez użycia Androida jako systemu operacyjnego (cena 200-500 zł). Żeby rozważyć kwestię smartwatchy musimy najpierw spojrzeć na komórki: czterordzeniowe ARMy, z 1GB RAM, TDP 2W, baterią 2000 mAh, działające na jednym ładowaniu 24h. W zegarku noszonym na ręce, który ma nie wyglądać na cegłę, bateria musi być sporo mniejsza, przyjmijmy że 10x, czyli 200 mAh. W rezultacie procesor musi być wyjątkowo prosty i energooszczędny - taktowany tyle co stare Pentium II, ale z TDP sporo poniżej 1W. System operacyjny musi być zatem uproszczony, gdzie zadanie ma do dyspozycji API do rysowania (konsola maksymalnie 256 kolorów), HTTP (nawet nie TCP/IP) i komunikację z hostem Bluetooth. Takim rozwiązaniem jest SoC MediaTek MT2502: cały układ o wymiarach 5.4 x 6.2 mm, CPU 260 MHz, 4MB RAM, 4MB Flash, sieć 2G. Po przeciwnej stronie tego segmentu musi być normalny system operacyjny przycięty do zastosowań osadzonych, ze wsparciem dla normalnych procesów, z wyświetlaczem z wysokim upakowaniem pikseli, z normalnym GUI, z procesorem ze sprzętowym dekodowaniem JPEG, z dużą i drogą baterią. Android Wear poprzez Google Play Store pozwala instalować aplikacje na zegarku.

 

HD CCTV z analogową transmisją danych cyfrowych

http://www.edn.com/design/analog/4402915/3/Transmitting-HD-video-over-RG-59-cable

Percentiles in HSQLDB

create AGGREGATE FUNCTION PERCENTILES(IN val float, IN flag_return boolean, INOUT buffer float ARRAY, INOUT counter INT)
   RETURNS varchar2
   CONTAINS SQL
   BEGIN ATOMIC
     declare i number default 1;
     declare stats varchar2(2000) default '';
     declare asum float default 0;  
     declare p0, p50, p90, p99, p100, pavg number default 0;
     declare sorted_buffer float ARRAY;
     IF flag_return THEN
       --call println('PERCENTILES return');
       set sorted_buffer = SORT_ARRAY(buffer);  
       call println('PERCENTILES sorted');
       set p50 = sorted_buffer[1];
       set p90 = sorted_buffer[1];
       set p99 = sorted_buffer[1];
       while i <= counter do
       begin atomic
  --call println('PERCENTILES selection '||i);
           set asum = asum + sorted_buffer[i];
           if abs(i - round(counter / 2, 0)) < 0.001 then
               set p50 = round(sorted_buffer[i], 2);
           end if;        
           if abs(i - round(counter * 9 / 10, 0)) < 0.001 then
               set p90 = round(sorted_buffer[i], 2);
           end if;
           if abs(i - round(counter  * 99 / 100, 0)) < 0.001 then
               set p99 = round(sorted_buffer[i], 2);
           end if;
  set i = i+1;        
       end;
       end while;
       set p0 = round(sorted_buffer[1],2);
       set p100 = round(sorted_buffer[counter],2);
       set pavg = round(asum / counter, 2);
       --call println('PERCENTILES preparing result');
       set stats = 'min='|| p0 || '|p50='|| p50 || '|p90='||p90 || '|p99='||p99 || '|max='||p100 || '|avg='|| pavg;
       RETURN stats;
     ELSE      
       IF val IS NULL THEN RETURN NULL; END IF;
       IF counter IS NULL THEN SET counter = 0; END IF;
       SET counter = counter + 1;
       IF counter = 1 THEN SET buffer = ARRAY[val];
       ELSE SET buffer[counter] = val; END IF;
       RETURN NULL;
     END IF;
   END

for (select appid, percentiles(mem_pct) as mem_stats, avg(mem_mb) as mem,
percentiles(cpu_pct) as cpu_stats, avg(cpu_cnt) as cpu,
    percentiles(gc_millis) as gc_stats from T_VM_STAT group by appid) do
  begin atomic
set r = REGEXP_SUBSTRING_ARRAY(mem_stats, '((?<==)[0-9]+[\.\,]*[0-9]*)');
set (p0,p50,p90,p99,p100,pavg)=(to_number(r[1]), to_number(r[2]), to_number(r[3]), to_number(r[4]), to_number(r[5]), to_number(r[6]));

Aerospike sever has got synchronization bugs :(

Bugs found during VAT testing (http://1307723433353.blogspot.com/2014/05/vat-validation-of-architecture-in-tests.html)

Aerospike is Open Source and if you encounter a problem you can analyze it yourself without waiting for the support in a different timezone. You can recompile fixed code and bring it immediately to the production. It is a way faster than with any platinum level support. You need only one guy who knows Linux and C.

Aerospike goes AIO!

Modified source code is here. I need to give it back to be compliant with GNU AGPLv3 licence.

Aerospike - fast or safe?

Let's look at https://github.com/aerospike/aerospike-server/blob/180ed47a5fffc54b3e45faccb33c908bc189db2e/as/src/storage/drv_ssd.c and try to find open() system call and fsync() system call. We see that open flags like O_SYNC are parametrized. There is also loop for fsync with parametrized sleep time. Relevant configuration (https://github.com/aerospike/aerospike-server/blob/master/as/src/base/cfg.c) lives in enable-osync and fsync-max-sec. Now, check default values at http://www.aerospike.com/docs/reference/configuration/. We see that synchronous writes are disabled by default, and fsync is also disabled. This means that there are no safety guaranties for single Aerospike node (see also: flush-max-ms). Due to asd/OS/storage crash data will likely be lost or corrupted. Probabilistic situation for 3 nodes on different racks with battery backed SSD array is quite different and the combined risk is very small (if we do not consider whole datacenter crash) and therefore Aerospike is acceptable solution with standard sane data safety/integrity/availability criteria.

EMS DS tracer

#include <stdio.h>
#include <stdlib.h>
#include <stdarg.h>
#include <unistd.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <string.h>
#include <dlfcn.h>
#include <execinfo.h>
#include <pthread.h>
#include <list>

const char interp[] __attribute__((section(".interp"))) = "/lib64/ld-linux-x86-64.so.2";

typedef int (*open_fn)(const char *path, int flags, ...);
typedef ssize_t (*write_fn)(int fd, const void *buf, size_t count);
typedef ssize_t (*writev_fn)(int fd, const struct iovec *iov, int count);
typedef ssize_t (*pwritev_fn)(int fd, const struct iovec *iov, int count, off_t offset);
typedef int (*ftruncate_fn)(int fd, off_t length);

static open_fn _open = NULL;
static open_fn _open64 = NULL;
static write_fn _write = NULL;
static writev_fn _writev = NULL;
static pwritev_fn _pwritev = NULL;
static ftruncate_fn _ftruncate = NULL;
static void *handle_libc = NULL;
static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER;

#define SYSOUTF(msg, params...) do { char buff[1024]; memset(buff, 0, 1024); snprintf(buff, 1024, msg, params); _write(1,buff,strlen(buff)); } while(0)
#define SYSOUT(msg) _write(1, msg, strlen(msg))

void __attribute__((constructor)) __init(void)
{
    if (handle_libc==NULL)
handle_libc = dlopen ("/lib64/libc.so.6", RTLD_NOW);
    if (handle_libc!=NULL) {
_open = (open_fn) dlsym(handle_libc, "open");
_open64 = (open_fn) dlsym(handle_libc, "open64");
_write = (write_fn) dlsym(handle_libc,"write");
_writev = (writev_fn) dlsym(handle_libc,"writev");
_pwritev = (pwritev_fn) dlsym(handle_libc,"pwritev");
_ftruncate = (ftruncate_fn) dlsym(handle_libc, "ftruncate");
SYSOUT("libemscompanion init completed\r\n");
    }
    else {
exit(-1);
    }
}

void __attribute__((destructor)) __fini(void)
{
    if (handle_libc!=NULL)
dlclose(handle_libc);
}

extern "C" {

    int open(const char *path, int flags, ...) {
va_list vargs;
va_start(vargs, flags);
mode_t mode = va_arg(vargs, mode_t);
va_end(vargs);
int ret = _open(path, flags, mode);
SYSOUTF("Open %s = %d\r\n", path, ret);
return ret;
    }
   
    int open64(const char *path, int flags, ...) {
va_list vargs;
va_start(vargs, flags);
mode_t mode = va_arg(vargs, mode_t);
va_end(vargs);
int ret = _open(path, flags, mode);
SYSOUTF("Open %s = %d\r\n", path, ret);
return ret;
    }
   
    ssize_t write(int fd, const void *buf, size_t count) {
off_t curr = lseek(fd, 0, SEEK_CUR);
SYSOUTF("Writing fd = %d, addr = %d, buff = %x, size = %d\r\n", fd, curr, buff, count);
ssize_t ret = _write(fd, buf, count);
return ret;
    }
}

extern "C" void _main(int argc, char **argv) {
    __init();
    SYSOUT("libEMSCompanion 0.0.1\r\n");
    exit(0);
}

EMS File Datastore as a sequential tx log

Writing fd = 9, addr = 24834560, buff = 8c405540, size = 512 (chunk header, const offset, every 1910272 bytes)
Writing fd = 9, addr = 22405120, buff = 8c405710, size = 861696 (full message with headers and body)
Writing fd = 9, addr = 23266816, buff = 8c405710, size = 861696
Writing fd = 9, addr = 26744832, buff = 8c405540, size = 512
Writing fd = 9, addr = 24128512, buff = 8c405710, size = 861696
Writing fd = 9, addr = 24990208, buff = 89c01820, size = 512
Writing fd = 9, addr = 1024, buff = 89c01820, size = 512
Writing fd = 9, addr = 1536, buff = 89c01820, size = 512
Writing fd = 9, addr = 24990720, buff = 89c01820, size = 512 (Client ACK record)
Writing fd = 9, addr = 24991232, buff = 89c01820, size = 512
Writing fd = 9, addr = 24991744, buff = 89c01820, size = 512
Writing fd = 9, addr = 24992256, buff = 89c01820, size = 512
Writing fd = 9, addr = 24992768, buff = 89c01820, size = 512
Writing fd = 9, addr = 24993280, buff = 89c01820, size = 512
Writing fd = 9, addr = 24993792, buff = 89c01820, size = 512
Writing fd = 9, addr = 24994304, buff = 89c01820, size = 512
Writing fd = 9, addr = 24994816, buff = 89c01820, size = 512
Writing fd = 9, addr = 24995328, buff = 89c01820, size = 512
Writing fd = 9, addr = 24995840, buff = 89c01820, size = 512
Writing fd = 9, addr = 24996352, buff = 89c01820, size = 512
Writing fd = 9, addr = 24996864, buff = 89c01820, size = 512
Writing fd = 9, addr = 24997376, buff = 89c01820, size = 512
Writing fd = 9, addr = 24997888, buff = 89c01820, size = 512
Writing fd = 9, addr = 24998400, buff = 89c01820, size = 512
Writing fd = 9, addr = 24998912, buff = 89c01820, size = 512
Writing fd = 9, addr = 24999424, buff = 89c01820, size = 512
Writing fd = 9, addr = 24999936, buff = 89c01820, size = 512
Writing fd = 9, addr = 25000448, buff = 89c01820, size = 512
Writing fd = 9, addr = 25000960, buff = 89c01820, size = 512
Writing fd = 9, addr = 25001472, buff = 89c01820, size = 512
Writing fd = 9, addr = 25001984, buff = 89c01820, size = 512
Writing fd = 9, addr = 25002496, buff = 89c01820, size = 512
Writing fd = 9, addr = 25003008, buff = 89c01820, size = 512
Writing fd = 9, addr = 25003520, buff = 89c01820, size = 512
Writing fd = 9, addr = 25004032, buff = 79ffa800, size = 512
Writing fd = 9, addr = 25004544, buff = 79ffa750, size = 512
Writing fd = 9, addr = 512, buff = 8c405710, size = 861696 (full message with headers and body, space reused)

Full messages and ACK records are laid out sequentially and interwoven. ACK doesn't clean up message header. This design under heavy load may lead to excessive datastore usage and need for frequent compaction maintenance.

JMS headers with almost nothing set take 213 bytes. Minus 28 bytes for JMSMessageID it is 185 bytes on disk.

Tibco BW Generic XPath Extractor

JBossTS recovery: look inside

10:40:44,801 (Thread-18) PeriodicRecovery: background thread Status <== SCANNING
10:40:44,801 (Thread-18) PeriodicRecovery: background thread scanning
10:40:44,802 (Thread-18) Periodic recovery - first pass <Wt, 30 wrz 2014 10:40:44>
10:40:44,802 (Thread-18) InputObjectState::InputObjectState()
10:40:44,802 (Thread-18) StatusModule: first pass
10:40:44,802 (Thread-18) HashedStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:40:44,802 (Thread-18) OutputObjectState::OutputObjectState()
10:40:44,890 (Thread-18) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ecce:542a6c31:53b
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ebbb:542a6bef:a98
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ed72:542a6c5e:50c
...

10:40:44,891 (Thread-18) [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
10:40:44,891 (Thread-18) InputObjectState::InputObjectState()
10:40:44,891 (Thread-18) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: )
10:40:44,892 (Thread-18) OutputObjectState::OutputObjectState()
10:40:44,892 (Thread-18)
10:40:44,896 (Thread-18) PERIODIC 1. PASS ON STORE  WITH TYPE /StateManager/AbstractRecord/XAResourceRecord
10:40:44,896 (Thread-18) [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
10:40:44,896 (Thread-18) InputObjectState::InputObjectState()
10:40:44,897 (Thread-18) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:40:44,897 (Thread-18) OutputObjectState::OutputObjectState()
10:45:42,120 (Thread-18) Periodic recovery - second pass <Wt, 30 wrz 2014 10:45:42>
10:45:42,120 (Thread-18) AtomicActionRecoveryModule: Second pass
10:45:42,136 (Thread-18) +---- RESOURCE INITIATED RECOVERY
10:45:42,136 (Thread-18) +--- RES RECOVERER: org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d
10:45:42,136 (Thread-18) org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d hasMoreResources
10:45:42,136 (Thread-18) org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d getXAResource
10:45:42,136 (Thread-18)  +-- CALLING XARECOVERY
10:45:42,136 (Thread-18) xarecovery of org.jboss.jms.server.recovery.MessagingXAResourceWrapper@53673666
10:45:42,136 (Thread-18) Recover java:DefaultEMSProvider
10:45:43,728 (Thread-18) [EMS] XA Recovery #15 sees 58 XIDs: [{formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:858-3f57c7ff:efbe:542a6d09:9aa}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:53b-3f57c7ff:ecce:542a6c31:693}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dad-3f57c7ff:f885:542a6d79:1efb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:537-3f57c7ff:ecce:542a6c31:688}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:514-3f57c7ff:ed72:542a6c5e:66d}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dd0-3f57c7ff:f885:542a6d79:1f13}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:26a-3f57c7ff:ef42:542a6ce0:3e1}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4f5-3f57c7ff:ed72:542a6c5e:63c}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:16b-3f57c7ff:eb5c:542a6bc7:2c3}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dbe-3f57c7ff:f885:542a6d79:1f14}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:333-3f57c7ff:ee22:542a6c8c:48d}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:166-3f57c7ff:eb5c:542a6bc7:2b8}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:aaf-3f57c7ff:ebbb:542a6bef:bfc}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:160-3f57c7ff:eafe:542a6b9a:2c8}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:2a1-3f57c7ff:ef42:542a6ce0:3ec}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:863-3f57c7ff:efbe:542a6d09:9bd}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1d93-3f57c7ff:f885:542a6d79:1ee5}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:47e-3f57c7ff:eeb2:542a6cb6:5cc}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:52c-3f57c7ff:ed72:542a6c5e:67e}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:1ad-3f57c7ff:eb5c:542a6bc7:2ef}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:879-3f57c7ff:efbe:542a6d09:9cb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:558-3f57c7ff:ecce:542a6c31:6a9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4ce-3f57c7ff:ed72:542a6c5e:626}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:304-3f57c7ff:ee22:542a6c8c:456}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:289-3f57c7ff:ef42:542a6ce0:3d6}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:183-3f57c7ff:eafe:542a6b9a:2d3}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:187-3f57c7ff:eb5c:542a6bc7:2d9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:18c-3f57c7ff:eafe:542a6b9a:2e9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:310-3f57c7ff:ee22:542a6c8c:461}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:31a-3f57c7ff:ee22:542a6c8c:471}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4df-3f57c7ff:ed72:542a6c5e:647}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:a98-3f57c7ff:ebbb:542a6bef:be6}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:16a-3f57c7ff:eb5c:542a6bc7:2ce}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:196-3f57c7ff:eb5c:542a6bc7:2e4}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:503-3f57c7ff:ed72:542a6c5e:652}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:54c-3f57c7ff:ecce:542a6c31:69e}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4e7-3f57c7ff:ed72:542a6c5e:631}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dd4-3f57c7ff:f885:542a6d79:1f27}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:176-3f57c7ff:eafe:542a6b9a:2bd}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1d9d-3f57c7ff:f885:542a6d79:1ef0}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:325-3f57c7ff:ee22:542a6c8c:477}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:46d-3f57c7ff:eeb2:542a6cb6:5c1}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4cd-3f57c7ff:ed72:542a6c5e:61b}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:464-3f57c7ff:eeb2:542a6cb6:5b6}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1db2-3f57c7ff:f885:542a6d79:1f1c}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:28a-3f57c7ff:ef42:542a6ce0:3cb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:33c-3f57c7ff:ee22:542a6c8c:482}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:86e-3f57c7ff:efbe:542a6d09:9c0}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:182-3f57c7ff:eafe:542a6b9a:2de}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:521-3f57c7ff:ed72:542a6c5e:673}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:19e-3f57c7ff:eb5c:542a6bc7:305}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:aa0-3f57c7ff:ebbb:542a6bef:bf9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:2ac-3f57c7ff:ef42:542a6ce0:3f7}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:f7d0:542a6d3a:5af-3f57c7ff:f7d0:542a6d3a:700}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:192-3f57c7ff:eb5c:542a6bc7:2fa}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:842-3f57c7ff:efbe:542a6d09:99f}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:50c-3f57c7ff:ed72:542a6c5e:65d}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:48d-3f57c7ff:eeb2:542a6cb6:5d7}]
10:45:43,730 (Thread-18) Found 58 xids in doubt

10:45:47,213 (Thread-18) +---- RESOURCE INITIATED RECOVERY completed
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:ecce:542a6c31:540) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:ecce:542a6c31:691
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 171 record
10:45:47,213 (Thread-18) StateManager::StateManager( 0:0:0:0 )
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor
10:45:47,213 (Thread-18) | RECOVERY XIDS for org.jboss.jms.server.recovery.MessagingXAResourceWrapper@2c8b18f5 contains -1217944454 ? true
10:45:47,213 (Thread-18) +---- RESOURCE INITIATED RECOVERY completed
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:ecce:542a6c31:540 -3f57c7ff:ecce:542a6c31:691) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:ecce:542a6c31:694
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 463 record
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_22] - HeuristicList - Unpacked heuristic list size of 0
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_25] - Restored action status of ActionStatus.COMMITTING 6
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_26] - Restored action type Top-level 0
10:45:47,215 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_27] - Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
10:45:47,215 (Thread-18) [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_1] - RecoverAtomicAction.replayPhase2 recovering -3f57c7ff:ecce:542a6c31:53b ActionStatus is ActionStatus.COMMITTED
10:45:47,215 (Thread-18) BasicAction::phase2Commit() for action-id -3f57c7ff:ecce:542a6c31:53b
10:45:47,215 (Thread-18) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@6fd5af22)
10:45:47,215 (Thread-18) XAResourceRecord.topLevelCommit for < 131075, 29, 27, 494545511025355995510210258101999910158535250975499514958535198455110253559955102102581019999101585352509754995149585351102 >
10:45:47,215 (Thread-18) [EMS] Recovery session will be created
10:45:47,216 (Thread-18) [EMS] Establishing handler for connection #-17

10:45:48,222 (Thread-18) BasicAction::updateState() for action-id -3f57c7ff:ecce:542a6c31:53b
10:45:48,222 (Thread-18) FileSystemStore.remove_committed(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:45:48,222 (Thread-18) ShadowingStore.remove_state(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#102#\-3f57c7ff_ecce_542a6c31_53b, FileLock.F_WRLCK, false)
10:45:48,223 (Thread-18) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#102#\-3f57c7ff_ecce_542a6c31_53b, null, null)
10:45:48,223 (Thread-18) [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_3] - RecoverAtomicAction.replayPhase2( -3f57c7ff:ecce:542a6c31:53b )  finished
10:45:48,223 (Thread-18) HashedStore.genPathName(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:45:48,223 (Thread-18) HashedStore.genPathName(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,224 (Thread-18) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:45:48,224 (Thread-18) InputObjectState::InputObjectState()
10:45:48,224 (Thread-18) HashedStore.allObjUids(/Recovery/TransactionStatusManager, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:45:48,224 (Thread-18) OutputObjectState::OutputObjectState()

Transactional MDB on JBoss 5: look inside

10:36:49,975 (Connection consumer 120) BaseTransaction.begin
10:36:49,975 (Connection consumer 120) StateManager::StateManager( 2 )
10:36:49,971 (Connection consumer 115) [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:a2 adding Thread[Connection consumer 115,5,JBoss Pooled Threads] result = true
10:36:49,975 (Connection consumer 120) BasicAction::BasicAction()
10:36:49,976 (Connection consumer 120) BasicAction::Begin() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:49,976 (Connection consumer 120) BasicAction::actionInitialise() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:49,976 (Connection consumer 120) ActionHierarchy::ActionHierarchy(5)
10:36:49,976 (Connection consumer 120) ActionHierarchy::add(-3f57c7ff:eafe:542a6b9a:ab, 1)
10:36:49,976 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:ab adding Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:49,976 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:ab adding Thread[Connection consumer 120,5,JBoss Pooled Threads] result = true
10:36:49,979 (Connection consumer 120) TransactionReaper::create ( 120000 )
10:36:49,979 (Connection consumer 120) TransactionReaper::insert ( BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING, 300 )
10:36:49,979 (Connection consumer 120) ReaperElement::ReaperElement ( BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING, 300 )
10:36:49,979 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue started transaction=TransactionImple < ac, BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING >
10:36:49,979 (Connection consumer 120) TransactionImple.enlistResource ( com.tibco.tibjms.XResource@4f9ee648 )
10:36:49,979 (Connection consumer 120) TransactionImple.getStatus
10:36:49,980 (Connection consumer 115) TransactionReaper::create ( 120000 )
10:36:49,980 (Connection consumer 120) StateManager::StateManager( 1 )
10:36:49,980 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:ad, 1)
10:36:49,971 (Thread-15) ReaperThread.run ()
10:36:49,980 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 > )
10:36:49,980 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:ad
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue enlisted=com.tibco.tibjms.XResource@4f9ee648
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue in use by public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message) Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue delivering
10:36:51,262 [org.jboss.ejb3.pool.StrictMaxPool] (Connection consumer 120) Acquired(true) strictMaxSize semaphore, remaining=0

10:36:51,262 INFO  [STDOUT] (Connection consumer 120) Received text: 2014-09-30T10:35:10.304+02:00 on test.fw1, id=ID:EMS-SERVER-DC2.2354542947B3299:101

10:36:52,330 (Connection consumer 120) TransactionImple.registerSynchronization
10:36:52,331 (Connection consumer 120) TransactionImple.enlistResource ( org.jboss.resource.adapter.jdbc.xa.XAManagedConnection@5c675382 )
10:36:52,331 (Connection consumer 120) TransactionImple.getStatus
10:36:52,331 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:1d1, 1)
10:36:52,331 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 > )
10:36:52,333 (Connection consumer 120) TransactionImple.enlistResource ( org.jboss.resource.adapter.jms.JmsXAResource@21f7e1c6 )
10:36:52,333 (Connection consumer 120) TransactionImple.getStatus
10:36:52,333 (Connection consumer 120) StateManager::StateManager( 1 )
10:36:52,333 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:1d7, 1)
10:36:52,333 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 > )
10:36:52,360 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad -3f57c7ff:eafe:542a6b9a:1d1) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d7
10:36:52,361 (Connection consumer 120) TransactionImple.getStatus
10:36:52,361 (Connection consumer 120) TransactionImple.getStatus
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) Invocation took 2412ms: public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message)
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue in use by public abstract void javax.resource.spi.endpoint.MessageEndpoint.afterDelivery() throws javax.resource.ResourceException Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:52,392 (Connection consumer 120) TransactionImple.equals
10:36:52,392 (Connection consumer 120) TransactionImple.getStatus
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue commit
10:36:52,392 (Connection consumer 120) BaseTransaction.commit
10:36:52,392 (Connection consumer 120) TransactionImple.commitAndDisassociate
10:36:52,392 (Connection consumer 120) SynchronizationImple.beforeCompletion

10:36:52,392 (Connection consumer 120) BasicAction::End() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,392 (Connection consumer 120) BasicAction::prepare () for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,392 (Connection consumer 120) ShadowingStore.ShadowingStore( 14 )
10:36:52,392 (Connection consumer 120) ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
10:36:52,392 (Connection consumer 120) HashedStore.HashedStore( 14 )
10:36:52,392 (Connection consumer 120) HashedStore.HashedActionStore()
10:36:52,392 (Connection consumer 120) FileSystemStore.setupStore()
10:36:52,392 (Connection consumer 120) FileSystemStore.createHierarchy(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\)
10:36:52,393 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 >
10:36:52,430 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:ad
10:36:52,430 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 >
10:36:52,494 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d1
10:36:52,494 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 >
10:36:52,556 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad -3f57c7ff:eafe:542a6b9a:1d1) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d7
10:36:52,557 (Connection consumer 120) OutputObjectState::OutputObjectState(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,557 (Connection consumer 120) BasicAction::save_state ()
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTING
10:36:52,557 (Connection consumer 120) FileSystemStore.write_committed(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,557 (Connection consumer 120) ShadowingStore.write_state(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,557 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,557 (Connection consumer 120) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, FileLock.F_WRLCK, true)
10:36:52,557 (Connection consumer 120) FileSystemStore.createHierarchy(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab)
10:36:52,647 (Connection consumer 120) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, null, java.io.FileOutputStream@7e1b811b)
10:36:52,651 (Connection consumer 120) BasicAction::phase2Commit() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,651 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@4407393d)
10:36:52,651 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 >
10:36:52,734 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@32955ada)
10:36:52,734 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 >
10:36:52,911 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@1cc05dc2)
10:36:52,911 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 >
10:36:52,947 (Connection consumer 120) BasicAction::updateState() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,947 (Connection consumer 120) FileSystemStore.remove_committed(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,947 (Connection consumer 120) ShadowingStore.remove_state(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, FileLock.F_WRLCK, false)
10:36:52,948 (Connection consumer 120) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, null, null)
10:36:52,948 (Connection consumer 120) SynchronizationImple.afterCompletion
10:36:52,948 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3f57c7ff:eafe:542a6b9a:ab removing TSThread:17
10:36:52,948 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_9] -  BasicAction::removeChildThread () action -3f57c7ff:eafe:542a6b9a:ab removing TSThread:17 result = true

Jak działa dbstore w EMS-ie

Klasa Javy com.tibco.tibems.tibemsd.internal.db.CallableDataStore jest używana przez kod C++ (poprzez JNI) do trzymania bieżących danych sterujących oraz zapisywania i odczytywania komunikatów. Do zapisywania wszystkich obiektów służy Hibernate:

[2014-09-09 10:48:28,006] DEBUG [tibemsd] (AbstractBatcher.java:424) - insert into EMS_MESSAGES (MESSAGE_SEQNO, TYPE, PRIORITY, DELIVERYMODE, REDELIVERED, DELIVERY_COUNT, DESTINATION, DESTINATION_TYPE, EXPIRATION, TIMESTAMP, DELIVERYTIME, REPLYTO, REPLYTO_TYPE, USERTYPE, MSGID, CORRELATIONID, COMPRESSED, CLIENTFLAGS, ENCODING, ENCODED_PROPERTIES, ENCODED_SUPPRESS_CONSIDS, TXNID, ZONEID, ROUTESRC, ROUTESEQNO, ROUTECONSID, PRODUCERID, DELETED, MESSAGE_SIZE, SMALL_MESSAGE_BODY, LARGE_MESSAGE_BODY, STORE_ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '337' to parameter: 1
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '3' to parameter: 2
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '4' to parameter: 3
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '2' to parameter: 4
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 5
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 6
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding 'test.fw1' to parameter: 7
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '1' to parameter: 8
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 9
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '1410252507549' to parameter: 10
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 11
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 12
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 13
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 14
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding 'ID:EMS-SERVER-DC2.23FC540EBDA24:2' to parameter: 15
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 16
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding 'false' to parameter: 17
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 18
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 19
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 20
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 21
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 22
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 23
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 24
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 25
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 26
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding '1' to parameter: 27
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding 'false' to parameter: 28
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding '123' to parameter: 29
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding '337' to parameter: 32
[2014-09-09 10:48:28,085] DEBUG [tibemsd] (AbstractBatcher.java:424) - select message0_.STORE_ID as STORE1_17_0_, message0_.MESSAGE_SEQNO as MESSAGE2_17_0_, message0_.TYPE as TYPE17_0_, message0_.PRIORITY as PRIORITY17_0_, message0_.DELIVERYMODE as DELIVERY5_17_0_, message0_.REDELIVERED as REDELIVE6_17_0_, message0_.DELIVERY_COUNT as DELIVERY7_17_0_, message0_.DESTINATION as DESTINAT8_17_0_, message0_.DESTINATION_TYPE as DESTINAT9_17_0_, message0_.EXPIRATION as EXPIRATION17_0_, message0_.TIMESTAMP as TIMESTAMP17_0_, message0_.DELIVERYTIME as DELIVER12_17_0_, message0_.REPLYTO as REPLYTO17_0_, message0_.REPLYTO_TYPE as REPLYTO14_17_0_, message0_.USERTYPE as USERTYPE17_0_, message0_.MSGID as MSGID17_0_, message0_.CORRELATIONID as CORRELA17_17_0_, message0_.COMPRESSED as COMPRESSED17_0_, message0_.CLIENTFLAGS as CLIENTF19_17_0_, message0_.ENCODING as ENCODING17_0_, message0_.ENCODED_PROPERTIES as ENCODED21_17_0_, message0_.ENCODED_SUPPRESS_CONSIDS as ENCODED22_17_0_, message0_.TXNID as TXNID17_0_, message0_.ZONEID as ZONEID17_0_, message0_.ROUTESRC as ROUTESRC17_0_, message0_.ROUTESEQNO as ROUTESEQNO17_0_, message0_.ROUTECONSID as ROUTECO27_17_0_, message0_.PRODUCERID as PRODUCERID17_0_, message0_.DELETED as DELETED17_0_, message0_.MESSAGE_SIZE as MESSAGE30_17_0_, message0_.SMALL_MESSAGE_BODY as SMALL31_17_0_, message0_.LARGE_MESSAGE_BODY as LARGE32_17_0_ from EMS_MESSAGES message0_ where message0_.STORE_ID=?
[2014-09-09 10:48:28,085] TRACE [tibemsd] (NullableType.java:133) - binding '247' to parameter: 1
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '247' as column: MESSAGE2_17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '3' as column: TYPE17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '4' as column: PRIORITY17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '2' as column: DELIVERY5_17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: REDELIVE6_17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: DELIVERY7_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning 'test.fw1' as column: DESTINAT8_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '1' as column: DESTINAT9_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: EXPIRATION17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '1410249505675' as column: TIMESTAMP17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: DELIVER12_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:166) - returning null as column: REPLYTO17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: REPLYTO14_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:166) - returning null as column: USERTYPE17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:172) - returning 'ID:EMS-SERVER-DC2.32DC540EB2EE4:141' as column: MSGID17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:166) - returning null as column: CORRELA17_17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:172) - returning 'false' as column: COMPRESSED17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: CLIENTF19_17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:166) - returning null as column: ENCODING17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:166) - returning null as column: ENCODED21_17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:166) - returning null as column: ENCODED22_17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: TXNID17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: ZONEID17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:166) - returning null as column: ROUTESRC17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: ROUTESEQNO17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: ROUTECO27_17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '1' as column: PRODUCERID17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning 'false' as column: DELETED17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '125' as column: MESSAGE30_17_0_

Gdyby numer sekwencji komunikatu był trzymany w bazie (Hibernate IdentifierGenerator = native/sequence) a nie był typem long trzymanym w pamięci to wiele instancji EMS-a mogłoby korzystać z tego samego schematu bazodanowego.

All server JVMs stats

for (VirtualMachineDescriptor vmd : VirtualMachine.list()) {
 VirtualMachine vm = VirtualMachine.attach(vmd);
 String javaHome = vm.getSystemProperties().getProperty("java.home");
 File managementAgentJarFile = new File(javaHome + File.separator + "lib" + File.separator + "management-agent.jar");
 vm.loadAgent(managementAgentJarFile.getAbsolutePath());
 String address =  vm.getAgentProperties().getProperty("com.sun.management.jmxremote.localConnectorAddress", null);
 JMXServiceURL jmxUrl = new JMXServiceURL(address);
 MBeanServerConnection conn = JMXConnectorFactory.connect(jmxUrl).getMBeanServerConnection();
 MemoryMXBean memBean = ManagementFactory.newPlatformMXBeanProxy(conn,
   ManagementFactory.MEMORY_MXBEAN_NAME, MemoryMXBean.class);
 RuntimeMXBean rtBean = ManagementFactory.newPlatformMXBeanProxy(conn,
   ManagementFactory.RUNTIME_MXBEAN_NAME, RuntimeMXBean.class);
 int memUsage = (int)(100.0 * memBean.getHeapMemoryUsage().getUsed() /  memBean.getHeapMemoryUsage().getMax());
 long memMB = memBean.getHeapMemoryUsage().getMax() / 1024 / 1024;
 System.out.println(rtBean.getSystemProperties().get("user.dir")+ " => " + memUsage +"% mem,   max="+memMB+"MB");
}

TDI can measure XML tree creation times per node

New build of TDI in profiler mode measures creation times per XML tree node. Presented time is an average with nanosecond accuracy, with given nesting level in XML tree.

Tibco flow tuning for high throughput

The most important settings are RAM, MaxJobs/FlowLimit, Engine.ThreadCount, HTTP Response Thread Pool size (type can be set to single for savings) and JMS MaxSessions (in client ack mode).
MaxSessions and MaxJobs should be equal per process, the same is true for correlated MaxJobs and HTTP Thread Pool. Engine.ThreadCount should be 10-20% greater than sum of FlowLimits, HTTP threads. When components are stacked every following should have FlowLimit exceeding previous by at least 20% (consider BW engine restarts and backlog). You can decrease RAM usage by tweaking XML namespaces usage (prefixes defined in process namespace registry should match prefixes used in activities, to get rid of redundant namespace declarations on every node you can 'exclude prefixes' from XML roots).
Interesting case is with huge volume of large messages (~1000 per second, > 100KB) handled by different processes of various duration: resource utilization is high and every process starter is flow controlled. When flow control kicks in it closes JMS receiver, it usually has got prefetched messages inside a session and all work for fetching them is lost and repeated by other receiver. Now, the default receive time unit is 1 second, which is not enough under heavy load. So, we've got the same messages floating and stuck between server and BW process. Overall performance is degraded very much. The solution is to disable prefetch and increase JMS receiver timeout. Described case can be traced with 'show consumers full' within tibemsadmin console.

EMS planetary pattern

EMS server holds its state and message structures in memory and therefore has a limit for maximal number of messages. Considering compiler options and memory alignment EMS server requires about 0,5KB per one JMS message. With EMS server using 4GB RAM you can have 8 mln messages.

When memory limit of EMS server is too low you can refactor your infrastructure with planetary pattern:

Applications have their local EMS instances with routing enabled towards master server and defined proxy queues:

billing.data@EMS-SERVER-MASTER store=$sys.failsafe,secure

billing.voice@EMS-SERVER-MASTER store=$sys.failsafe,secure

billing.premium@EMS-SERVER-MASTER store=$sys.failsafe,secure

Master server has limits forced on these queues:

billing.data@EMS-SERVER-MASTER store=$sys.failsafe,secure,maxmsgs=1000000

billing.voice@EMS-SERVER-MASTER store=$sys.failsafe,secure,maxmsgs=1000000

billing.premium@EMS-SERVER-MASTER store=$sys.failsafe,secure,maxmsgs=1000000

When you send messages to local server's queue and master server still has got free capacity - they are routed. When master's limit is reached messages are stored on local server - until master regained capacity.

With EMS planetary pattern you can get rid of EMS server memory limits. If client connects to EMS server via JNDI it can be transparently redirected to other server, so you can migrate easily from single server to planetary infrastructure. If connection factory config is taken from local JNDI you can add additional server behind local EMS without reconfiguring client.

Tibco BusinessWorks 6.0 is coming

ActiveMatrix application server concept has failed as a product and Tibco is changing its focus back to BW. BW 6.0 at the component level will be OSGI based and will allow for custom plugins via stable and well defined interface. No hacking, no Java glue - you will be able to easily deliver needed functionalities. Adapters are gone, they are replaced by Java-based plugins. SAP activities will run at the component level (ouch, possible licensing issues). BW 6.0 beta is going through QA tests - it should be available by the end of year. BW 5.x will be long term supported.

Tibco BW HealthCheck pattern

It is possible for every BW component exposing services via HTTP or JMS to create HealthCheck process. It can be started with HTTP Receiver (no SOAPAction header) or JMS Receiver (Ping property used with JMS selector). Process should ping uderlying components or external systems and return success of failure status. Also it is possible to get current CPU/GC/MEM usage from JMX and Tibco BW processes statistics from Hawk. You open one URL and get detailed statistics from which you can check overal health of flows.