IBM WebSphere Application Server Performance Cookbook

IBM Sterling

IBM Sterling B2B Integrator

tlsDefaultThreadsPerAdapter

A large volume of concurrent TLS handshakes may cause a performance issue because the perimeter server defaults the thread pool to perform TLS handshakes to a maximum value of 1. This may be increased by setting perimeterServices.tlsDefaultThreadsPerAdapter=N in perimeter.properties.

Symptoms of this problem include:

  1. Slow FM68 handshake times in B2Bi Perimeter.log with the DEBUG trace level between accepting a socket; for example: 
    [2025-10-01 12:34:34.725] COMMTRACE <Dispatcher> Listen[0.0.0.0/0.0.0.0:11364]: accepted: /10.1.2.3:52631
    And the CD Interop layer reading the FM68 from the network: 
    [2025-10-01 12:39:50.959] DEBUG <Thread-17876> ConduitStreamPair{cdinteroplogger:10.1.2.3|52631|10.1.2.4|11364}-is.read() - Read 16 bytes
  2. B2Bi tcpdumps showing a TCP handshake, followed by an incoming BEGNchr4FM68, followed by the client timing out its half of the socket, followed by B2Bi responding with BEGNchr4FM68; for example: 
    No.     Time                          Source                SourcePort Destination           DestinationPort Stream     Length Info
1469479 2025-10-01 12:34:34.682519    10.101.11.1           52631      10.101.10.101         11364           15271      66     52631 → 11364 [SYN, ECE, CWR] Seq=0 Win=64240 Len=0 MSS=1230 WS=256 SACK_PERM
1469480 2025-10-01 12:34:34.682539    10.101.10.101         11364      10.101.11.1           52631           15271      66     11364 → 52631 [SYN, ACK] Seq=0 Ack=1 Win=65280 Len=0 MSS=1360 SACK_PERM WS=2
1469694 2025-10-01 12:34:34.725004    10.101.11.1           52631      10.101.10.101         11364           15271      54     52631 → 11364 [ACK] Seq=1 Ack=1 Win=262656 Len=0
1469798 2025-10-01 12:34:34.742860    10.101.11.1           52631      10.101.10.101         11364           15271      266    52631 → 11364 [PSH, ACK] Seq=1 Ack=1 Win=262656 Len=212
[...]
0040  00 c0 80 00 00 00 ba 00 00 00 42 45 47 4e 63 68   ..........BEGNch
0050  72 34 46 4d 36 38                                 r4FM68
1469799 2025-10-01 12:34:34.742878    10.101.10.101         11364      10.101.11.1           52631           15271      54     11364 → 52631 [ACK] Seq=1 Ack=213 Win=65200 Len=0
1967536 2025-10-01 12:37:34.989921    10.101.11.1           52631      10.101.10.101         11364           15271      54     52631 → 11364 [FIN, ACK] Seq=213 Ack=1 Win=262656 Len=0
1967670 2025-10-01 12:37:35.030892    10.101.10.101         11364      10.101.11.1           52631           15271      54     11364 → 52631 [ACK] Seq=1 Ack=214 Win=65200 Len=0
2347740 2025-10-01 12:39:50.960315    10.101.10.101         11364      10.101.11.1           52631           15271      210    11364 → 52631 [PSH, ACK] Seq=1 Ack=214 Win=65200 Len=156
[....]
0040  00 88 00 00 00 00 ba 00 00 00 42 45 47 4e 63 68   ..........BEGNch
0050  72 34 46 4d 36 38                                 r4FM68
  3. CSPA003E and/or CSPA010E timeouts in IBM Sterling Connect:Direct; for example: 
    BEGN=STRS|STDL=20251001 093734[...]MSGI=CSPA003E|SBST=(&FUNC=chk_rmt_error,&DIAG=recv'd remote node error)|FDBK=0|STSD=2|TZDI=-10800|MSST=Security Violation - SNODE authentication error|END =STRS|

BEGN=STRS|STDL=20251001 093734[...]MSGI=LIPT016I|FDBK=0|STSD=1|TZDI=-10800|MSST=The call to read_retry() failed. OS Msg=10060.|END =STRS|

BEGN=STRS|STDL=20251001 093734[...]MSGI=LIPT011I|SBST=(&OSMSG=10060,&DIAG=tcp.max.time.to.wait expired)|FDBK=0|STSD=0|TZDI=-10800|MSST=The call to read the TCP/IP data failed - OS error 10060.|END =STRS|

BEGN=STRS|STDL=20251001 0934342[...]MSGI=LSMG200I|[...]MSST=Process number 3759 (name X, SNODE Y) executing|END =STRS|

Wireshark Lua script to find FM68 delays in tcpdump

tcpdump with -s 100 was sufficient to capture the FM68s.

b2bifm68responsetimes.lua:

-- Usage: tshark -q -r $PCAP -X lua_script:b2bifm68responsetimes.lua
-- This script is provided as-is without any warranty or support.

local totalPackets = 0
local firstTime = nil
local lastTime = nil
local destination_port = 11364

do
  print("FM68TimeOfResponse,FM68ResponseTime(s),EphemeralPort")

  -- Fields we're using
  local frame_time = Field.new("frame.time")
  local frame_number = Field.new("frame.number")
  local tcp_stream = Field.new("tcp.stream")
  local tcp_flags_syn = Field.new("tcp.flags.syn")
  local tcp_flags_ack = Field.new("tcp.flags.ack")
  local tcp_flags_fin = Field.new("tcp.flags.fin")
  local tcp_srcport = Field.new("tcp.srcport")
  local tcp_dstport = Field.new("tcp.dstport")

  local streams = {}

  local function init_listener()
    local tap = Listener.new("tcp", "tcp.port == " .. tostring(destination_port))

    function tap.reset()
      
    end

    function tap.packet(pinfo,tvb)
      local frametime = tostring(frame_time())
      local framenumber = tonumber(tostring(frame_number()))
      local stream = tonumber(tostring(tcp_stream()))
      local srcport = tonumber(tostring(tcp_srcport()))
      local dstport = tonumber(tostring(tcp_dstport()))
      local stateMachine = streams[stream]
      if stateMachine == nil then
        streams[stream] = {
          state = 0,
          started = nil,
          acked_first_interaction = nil,
          acked_first_interaction_str = nil,
        };
        stateMachine = streams[stream]
      end

      totalPackets = totalPackets + 1
      if firstTime == nil then
        firstTime = frametime
      end
      lastTime = frametime

      if tostring(tcp_flags_syn()) == "True" and tostring(tcp_flags_ack()) == "False" and dstport == destination_port then
        -- Start of a handshake: SYN
        stateMachine.state = 1
        stateMachine.started = frame_time()()
      else
        if stateMachine.state == 1 then
          -- We expect a syn/ack here
          if tostring(tcp_flags_syn()) == "True" and tostring(tcp_flags_ack()) == "True" then
            stateMachine.state = 2
          else
            -- Not a SYN/ACK, might be something else like a RST or FIN
            stateMachine.state = 0
          end
        elseif stateMachine.state == 2 then
          -- We expect this is just an ACK
          stateMachine.state = 3
        elseif stateMachine.state == 3 then
          -- We expect a client packet
          stateMachine.state = 4
        elseif stateMachine.state == 4 then
          -- We expect we'll ACK the client packet
          stateMachine.state = 5

          -- Now save off the time
          stateMachine.acked_first_interaction = frame_time()()
          stateMachine.acked_first_interaction_str = frametime
        elseif stateMachine.state == 5 then

          -- This could either be a FIN timeout from the client or the FM68 response
          if tostring(tcp_flags_fin()) == "True" then
            stateMachine.state = 6
          else
            stateMachine.state = 0
            local timeSinceFirstInteraction = frame_time()() - stateMachine.acked_first_interaction
            local timeSinceFirstInteractionSeconds = (timeSinceFirstInteraction.secs + (timeSinceFirstInteraction.nsecs / 1000000000))
            print("\"" .. frametime .. "\"," .. string.format("%.3f",timeSinceFirstInteractionSeconds) .. "," .. tostring(dstport))
          end
        elseif stateMachine.state == 6 then
          -- This should be the ACK to the FIN
          stateMachine.state = 7
        elseif stateMachine.state == 7 then
          stateMachine.state = 0
          local timeSinceFirstInteraction = frame_time()() - stateMachine.acked_first_interaction
          local timeSinceFirstInteractionSeconds = (timeSinceFirstInteraction.secs + (timeSinceFirstInteraction.nsecs / 1000000000))
          print("\"" .. frametime .. "\"," .. string.format("%.3f",timeSinceFirstInteractionSeconds) .. "," .. tostring(dstport))
        end
      end
    end
    
    function tap.draw()
    end
  end

  init_listener()
end

Awk script to find FM68 delays in Perimeter*.log

Example usage:

$ ~/b2b_perimeter_fm68_response_times.awk -v threshold=180000 Perimeter.log* | head
FM68ResponseTime,FM68ArrivalTime,FM68Duration(ms),SourcePort,DestPort,FM68ArrivalFile,FM68ResponseFile
2025-10-01 12:39:50,2025-10-01 12:35:30,260684,64888,11364,Perimeter.log.D20251001.T123526,Perimeter.log.D20251001.T123949
2025-10-01 12:39:50,2025-10-01 12:34:57,293030,50765,11364,Perimeter.log.D20251001.T123359,Perimeter.log.D20251001.T123949
2025-10-01 12:39:50,2025-10-01 12:35:38,252473,59851,11364,Perimeter.log.D20251001.T123526,Perimeter.log.D20251001.T123949
2025-10-01 12:39:50,2025-10-01 12:35:16,274794,52734,11364,Perimeter.log.D20251001.T123359,Perimeter.log.D20251001.T123949
2025-10-01 12:39:50,2025-10-01 12:35:53,237439,63062,11364,Perimeter.log.D20251001.T123526,Perimeter.log.D20251001.T123949
2025-10-01 12:39:50,2025-10-01 12:35:12,278518,50026,11364,Perimeter.log.D20251001.T123359,Perimeter.log.D20251001.T123949
2025-10-01 12:39:50,2025-10-01 12:35:26,264942,49508,11364,Perimeter.log.D20251001.T123359,Perimeter.log.D20251001.T123949
2025-10-01 12:39:50,2025-10-01 12:35:31,259885,56300,11364,Perimeter.log.D20251001.T123526,Perimeter.log.D20251001.T123949
2025-10-01 12:39:50,2025-10-01 12:35:21,269055,64859,11364,Perimeter.log.D20251001.T123359,Perimeter.log.D20251001.T123949

b2b_perimeter_fm68_response_times.awk:

#!/usr/bin/awk -f
# This script is provided as-is without any warranty or support.
# 
# b2b_perimeter_fm68_response_times.awk: Find per-socket durations between reading
# the FM68 on Dispatcher and writing the FM68 by CDInterop
#
# usage: b2b_perimeter_fm68_response_times.awk [-v threshold=MS] FILE+
#        FILE+: Time-sorted Perimeter.log* file(s) with debug trace
#        threshold=MS: Only print matches greater than MS milliseconds. Default 0.
 
BEGIN {
  TIME_INFO_YEAR = 1;
  TIME_INFO_MONTH = 2;
  TIME_INFO_DAY = 3;
  TIME_INFO_HOUR = 4;
  TIME_INFO_MINUTE = 5;
  TIME_INFO_SECOND = 6;
  TIME_INFO_MILLISECOND = 7;
  TIME_INFO_SUM_MILLISECONDS_DAY = 8;
  TIME_INFO_SUM_MILLISECONDS_TIME = 9;
  TIME_INFO_SUM_MILLISECONDS_DAY_TIME = 10;
 
  MILLISECONDS_IN_YEAR = 1000 * 60 * 60 * 24 * 365;
  MILLISECONDS_IN_MONTH = 1000 * 60 * 60 * 24 * 30;
  MILLISECONDS_IN_DAY = 1000 * 60 * 60 * 24;
  MILLISECONDS_IN_HOUR = 1000 * 60 * 60;
  MILLISECONDS_IN_MINUTE = 1000 * 60;
 
  if (length(threshold) == 0) {
    threshold = 0;
  }
  print "FM68ResponseTime,FM68ArrivalTime,FM68Duration(ms),SourcePort,DestPort,FM68ArrivalFile,FM68ResponseFile";
}
 
# Functions cannot return arrays, so use a global variable
function extractTimeFromString(str) {
  delete timeInfo;
  result = 0;
 
  i = match(str, /20[0-9][0-9]-[0-9]+-[0-9]+ [0-9]+:[0-9]+:[0-9]+\.[0-9]+/);
  if (i) {
    result = 1;
    timestampAndAfter = substr(str, i);
 
    i = match(timestampAndAfter, /-/);
    year = 0 + substr(timestampAndAfter, 1, i - 1);
    timestampAndAfter = substr(timestampAndAfter, i + 1);
 
    i = match(timestampAndAfter, /-/);
    month = 0 + substr(timestampAndAfter, 1, i - 1);
    timestampAndAfter = substr(timestampAndAfter, i + 1);
 
    i = match(timestampAndAfter, / /);
    day = 0 + substr(timestampAndAfter, 1, i - 1);
    timestampAndAfter = substr(timestampAndAfter, i + 1);
 
    i = match(timestampAndAfter, /:/);
    hour = 0 + substr(timestampAndAfter, 1, i - 1);
    timestampAndAfter = substr(timestampAndAfter, i + 1);
 
    i = match(timestampAndAfter, /:/);
    minute = 0 + substr(timestampAndAfter, 1, i - 1);
    timestampAndAfter = substr(timestampAndAfter, i + 1);
 
    i = match(timestampAndAfter, /\./);
    second = 0 + substr(timestampAndAfter, 1, i - 1);
    timestampAndAfter = substr(timestampAndAfter, i + 1);
 
    gsub(/[^0-9].*/, "", timestampAndAfter);
    if (length(timestampAndAfter) == 1) {
      millisecond = (0 + timestampAndAfter) * 100;
    } else if (length(timestampAndAfter) == 2) {
      millisecond = (0 + timestampAndAfter) * 10;
    } else if (length(timestampAndAfter) == 3) {
      millisecond = 0 + timestampAndAfter;
    } else {
      print "ERROR: Unexpected: " $0;
      exit 1;
    }
 
    timeInfo[TIME_INFO_YEAR] = year;
    timeInfo[TIME_INFO_MONTH] = month;
    timeInfo[TIME_INFO_DAY] = day;
    timeInfo[TIME_INFO_HOUR] = hour;
    timeInfo[TIME_INFO_MINUTE] = minute;
    timeInfo[TIME_INFO_SECOND] = second;
    timeInfo[TIME_INFO_MILLISECOND] = millisecond;
 
    timeInfo[TIME_INFO_SUM_MILLISECONDS_DAY] = (day * MILLISECONDS_IN_DAY) + (month * MILLISECONDS_IN_MONTH) + (year * MILLISECONDS_IN_YEAR);
    timeInfo[TIME_INFO_SUM_MILLISECONDS_TIME] = millisecond + (second * 1000) + (minute * MILLISECONDS_IN_MINUTE) + (hour * MILLISECONDS_IN_HOUR);
    timeInfo[TIME_INFO_SUM_MILLISECONDS_DAY_TIME] = timeInfo[TIME_INFO_SUM_MILLISECONDS_DAY] + timeInfo[TIME_INFO_SUM_MILLISECONDS_TIME];
  }
 
  return result;
}
 
function extractTimeFromMilliseconds(t) {
  delete timeInfo;
 
  timeInfo[TIME_INFO_YEAR] = 0;
  timeInfo[TIME_INFO_MONTH] = 0;
  timeInfo[TIME_INFO_DAY] = 0;
  timeInfo[TIME_INFO_HOUR] = 0;
  timeInfo[TIME_INFO_MINUTE] = 0;
  timeInfo[TIME_INFO_SECOND] = 0;
  timeInfo[TIME_INFO_MILLISECOND] = 0;
 
  if (t >= MILLISECONDS_IN_YEAR) {
    timeInfo[TIME_INFO_YEAR] = int(t / MILLISECONDS_IN_YEAR);
    t = t % MILLISECONDS_IN_YEAR;
  }
  if (t >= MILLISECONDS_IN_MONTH) {
    timeInfo[TIME_INFO_MONTH] = int(t / MILLISECONDS_IN_MONTH);
    t = t % MILLISECONDS_IN_MONTH;
  }
  if (t >= MILLISECONDS_IN_DAY) {
    timeInfo[TIME_INFO_DAY] = int(t / MILLISECONDS_IN_DAY);
    t = t % MILLISECONDS_IN_DAY;
  }
  if (t >= MILLISECONDS_IN_HOUR) {
    timeInfo[TIME_INFO_HOUR] = int(t / MILLISECONDS_IN_HOUR);
    t = t % MILLISECONDS_IN_HOUR;
  }
  if (t >= MILLISECONDS_IN_MINUTE) {
    timeInfo[TIME_INFO_MINUTE] = int(t / MILLISECONDS_IN_MINUTE);
    t = t % MILLISECONDS_IN_MINUTE;
  }
  if (t >= 1000) {
    timeInfo[TIME_INFO_SECOND] = int(t / 1000);
    t = t % 1000;
  }
  if (t > 0) {
    timeInfo[TIME_INFO_MILLISECOND] = t;
  }
}
 
function getTimeInfoAsStringYYYYMMDDSPACEHHMMSS() {
  return sprintf("%04d-%02d-%02d %02d:%02d:%02d", timeInfo[TIME_INFO_YEAR], timeInfo[TIME_INFO_MONTH], timeInfo[TIME_INFO_DAY], timeInfo[TIME_INFO_HOUR], timeInfo[TIME_INFO_MINUTE], timeInfo[TIME_INFO_SECOND]);
}
 
function getTimeInfoAsStringYYYYMMDDSPACEHHMMSSm() {
  result = sprintf("%04d-%02d-%02d %02d:%02d:%02d", timeInfo[TIME_INFO_YEAR], timeInfo[TIME_INFO_MONTH], timeInfo[TIME_INFO_DAY], timeInfo[TIME_INFO_HOUR], timeInfo[TIME_INFO_MINUTE], timeInfo[TIME_INFO_SECOND]);
  milliseconds = sprintf("%d", timeInfo[TIME_INFO_MILLISECOND]);
  if (length(milliseconds) == 1) {
    milliseconds = milliseconds "00";
  } else if (length(milliseconds) == 2) {
    milliseconds = milliseconds "0";
  } else if (length(milliseconds) > 3) {
    print "ERROR: Unpexpected milliseconds length for " milliseconds;
    exit 1;
  }
  return result "." milliseconds;
}
 
function getTimeInfoAsStringYYYYMMDD() {
  return sprintf("%04d-%02d-%02d", timeInfo[TIME_INFO_YEAR], timeInfo[TIME_INFO_MONTH], timeInfo[TIME_INFO_DAY]);
}
 
function getTimeInfoAsStringHHMMSS() {
  return sprintf("%02d:%02d:%02d", timeInfo[TIME_INFO_HOUR], timeInfo[TIME_INFO_MINUTE], timeInfo[TIME_INFO_SECOND]);
}
 
function trimWhitespace(str) {
  gsub(/[ \t\n\r]+/, "", str);
  return str;
}
 
function escapeCSV(str) {
  if (str ~ /,/ || str ~ /\n/ || str ~ /"/) {
    gsub(/"/, "\"\"", str);
    str = "\"" str "\"";
  }
  return str;
}
 
/COMMTRACE <Dispatcher> data.*: read bytes: / {
  if (extractTimeFromString($0)) {
    # Only on the first read
    ipinfo = $5;
    gsub(/data\[\//, "", ipinfo);
    gsub(/=>\//, ":", ipinfo);
    gsub(/\]:/, "", ipinfo);
    split(ipinfo, ippieces, /:/);
    destip = ippieces[1];
    destport = ippieces[2];
    srcip = ippieces[3];
    srcport = ippieces[4];
    if (!(srcip ~ /[0-9]+\./)) {
      print "ERROR: Unexpected: " $0;
      exit 1;
    }
 
    # Only track the first read
    if (!perimiterStarts[srcip,srcport]) {
      perimiterStarts[srcip,srcport] = timeInfo[TIME_INFO_SUM_MILLISECONDS_DAY_TIME];
      perimiterLines[srcip,srcport] = $0;
      perimiterFiles[srcip,srcport] = FILENAME;
    }
  } else {
    print "ERROR: Unexpected: " $0;
    exit 1;
  }
}
 
/DEBUG <Thread-.*> ConduitStreamPair.cdinteroplogger:.*-os.write.* - writing .* bytes/ {
  if (extractTimeFromString($0)) {
    ipinfo = $5;
    gsub(/.*cdinteroplogger:/, "", ipinfo);
    gsub(/}-is.read.*/, "", ipinfo);
    split(ipinfo, ippieces, /\|/);
    destip = ippieces[3];
    destport = ippieces[4];
    srcip = ippieces[1];
    srcport = ippieces[2];
    if (!(srcip ~ /[0-9]+\./)) {
      print "ERROR: Unexpected: " $0;
      exit 1;
    }
    if (perimiterStarts[srcip,srcport]) {
      cdinteropStarted = timeInfo[TIME_INFO_SUM_MILLISECONDS_DAY_TIME];
      perimeterStarted = perimiterStarts[srcip,srcport];
      diff = cdinteropStarted - perimeterStarted;
      if (diff >= threshold) {
        extractTimeFromMilliseconds(timeInfo[TIME_INFO_SUM_MILLISECONDS_DAY_TIME]);
        responseTime = getTimeInfoAsStringYYYYMMDDSPACEHHMMSS();
        extractTimeFromMilliseconds(perimeterStarted);
        arrivalTime = getTimeInfoAsStringYYYYMMDDSPACEHHMMSS();
 
        printf("%s,%s,%d,%d,%d,%s,%s\n", responseTime, arrivalTime, diff, srcport, destport, escapeCSV(perimiterFiles[srcip,srcport]), escapeCSV(FILENAME));
      }
      perimiterStarts[srcip,srcport] = 0;
    }
  } else {
    print "ERROR: Unexpected: " $0;
    exit 1;
  }
}