Interpret Diagnostic Data¶

Interpret Diagnostic Data

Thread dump interpretation¶

FWD has many threads in a fully-fledged server deployment, so thread dumps can get quite tedious to analyze. The good interpretation of such thread dumps heavily relies on the ability to isolate relevant parts of the thread dumps.

TBD: Show a diagram of the per-session thread design in FWD.
TBD: Show a diagram of the different session and process types and how they fit into the FWD design and map to the legact OE concepts.
TBD: Provide a more detailed mapping of the thread names to their purpose (in a table), including both FWD and non-FWD threads.

Identifying relevant thread dumps¶

FWD architecture has several Java processes running under the hood. The most relevant and resource demanding one is the server as it is the only actor that effectively runs converted code. That is being said, threads dumps onto the server's JVM are most the relevant for analysis, mostly because all client sessions (e.g. ChUI/GUI sessions including Web, appservers, batch processes) have a very descriptive state on the server.

However, each spawned client also has a Java process running on spawner's machine. Thus, a thread-dump on a specific client can be done to retrieve non-server specifics like drawing, event processing, etc.

Structure of a thread dump¶

The structure of such file is quite trivial as is simply contains information on each thread, listed one after the other, separated by a new line. Each thread inside the server JVM has:

"main" - Thread t@1 - the name of the thread (i.e. "main") followed by an unique order number
java.lang.Thread.State: RUNNABLE - a state in which the thread is, out of which the most important are:
- RUNNABLE threads are actively working on the CPU.
- TIMED_WAITING / WAITING threads are stuck on an operation that requires them to wait like Object.wait (eventually with a timeout)
the full stack trace of the thread. The first entry is representing where the thread currently is, while the bottom line is the origin of the thread (i.e. a Thread.run call)
- sometimes, some lines are simply waiting on, representing that the WAIT state is generated by a .wait on a specific resource, whose id is provided.
- sometimes, some linea are simply - locked, representing the implicit locks done by synchronized calls
Locked ownable synchronizers are the explicit locks (i.e. .lock) done by the thread

Identifying relevant threads inside a server thread dump¶

Discussing specifically about FWD, the interpretation of the thread dump may rely on the name of threads:

PSTimer threads can be skipped. They represent an implementation of the PSTimer OCX that is meant to generate Tick events. Its job is not related to any converted business logic.
C3P0PooledConnectionPoolManager are threads specific to the c3p0 3rd party dependency of FWD. This does the management of pooled connections to the database. This is unrelated to converted business logic.
Reader / Writer / Conversation are threads specific to one client session that requested converted code to be executed. This means that there may be multiple such threads, depending on the number of user sessions. Reader and Writer are threads that handle the communication protocol with the Java client asynchronously. Conversation is the actual synchronous thread that runs converted code.
qtp* prefixed thread names are specific to Jetty's Queued Thread Pool. This is unrelated to converted business logic.
SOAP Worker threads are responsible for SOAP services enabled through appservers. These are unrelated to converted business logic, as the real SOAP request is processed through converted business logic inside a Conversation thread.
AgentStopper threads are responsible for handling STOP requests on appservers asynchronously. They are usually in a WAIT state going into RUNNABLE when a STOP request is received.

Conversation threads on server thread dump¶

Each ChUI/GUI client session, appserver or batch process is considered a client to the server. That means that any of these have a Reader / Writer / Conversation group within the server.

ChUI/GUI client sessions that are spawned for Web usage have the name "[<id>:bogus]", where the <id> is used to uniquely identify such client sessions
appservers have the name "[<id>:<appserver-name>]", where the <id> is used to uniquely identify the appserver and the <name> is used to identify the appserver type
batch processes "[<id>:<batch-process-name>]", here the <id> is used to uniquely identify the appserver and the <batch-process-name> is used to identify the actual process

As the Conversation thread is the one relevant here, so we can cut out the thread dump only to bogus, appserver or batch-process conversation threads. This will greatly reduce the quantity of information to analyze.

Stack trace interpretation on server thread dump¶

If the server is not used 100% at a specific time (aka all conversations are RUNNABLE), then the trivial WAITING conversations can be skipped:

client sessions that are inside an WAIT-FOR can be skipped. This can be easily identified if the top of the stack contains com.goldencode.p2j.ui.LogicalTerminal.waitFor(LogicalTerminal.java:7048), followed by some internal methods that end up in java.base@17.0.11/java.lang.Object.wait
appservers that are inside com.goldencode.p2j.util.Agent.listen and not much else can be disregarded as they are simply provisioned, but not doing any work yet.
batch processes are usually spending time in some kind of WAIT if they have nothing to actually process. This is customer specific, but usually is something like a PAUSE statement that is run within a repeat loop.

Considering such clear-up is being done, there shouldn't be that threads left for analysis.

Identifying issues in a single server stack trace¶

There are plenty of things too look for inside a stack trace and most of the time these only provide hints for potential issues. The thread-dumps are not 100% reliable in telling what the problem is, but rather create a context in which futher debugging and experimentation can take place. Unfortunately, only single stack trace is not enough to state whether the problem is an infinite loop, slow process, etc. It can simply provide more context to where the problem might be:

lines starting with com.goldencode.p2j are specific to FWD run-time. They can be either:
- terminal behavioral patterns, which imply that FWD is delegated to do something that won't require converted code anymore (FIND statement, DISPLAY statement, etc.). Usually these appear in the top of the stack and can eventually delegate work further to a 3rd party (i.e. PostgreSQL query) or to the client (i.e. ThinClient.display that will continue execution on the client).
- intermediate behavioral patterns, which imply that FWD is only used to transition the control flow from one piece of converted code to another (i.e. RUN, trigger invocation, etc.). These parts appear lower down the stack. They should be collapsed and usually ignored altogehter.
lines starting with customer specific package refer to, of course, customer specific code. These provide valuable insight on where the control flow propagates through the converted application and understand what exactly was happening at that time.

Specifics:

lines like sun.nio.ch.Net.poll indicate that an external IO is happening. Down the stack there can be a org.postgresql.core specific line, hinting that currently a command is being executed in the DB. This may be a long running query or a query that is constantly being executed.
TODO

Identifying issues in multiple server stack traces¶

Because client sessions are identifiable by names and ids, one can follow the life of one session across multiple minutes. In this case, the following can be detected:

Infinite loop: if a certain thread is displaying very similar stack traces across multiple minutes, that this might be a proof of an infinite loop. The root cause is usually the common prefix stack across all thread dumps (e.g a forEach block, a doWhile block, etc.). However, this pattern is not always hinting an infinite loop. If the business logic was intended to actually have many iterations with a specific loop structure, than it may be easily mistaken for a very long running process.
Very long running process: this has the same symptoms as an infinite loop. It is hard to distinguish in between them.
Dead-lock: FWD level dead locks can be easily identified by checking which threads are in WAIT state due to the need of acquiring a lock. As this is available in the thread dump together with the locks that the thread actually has, then it is easier to cross-check which threads are dead-lockde. However, converted code level dead locks are way harder to be identified as it requires expertise in cross-checking stack traces in order to identify synchronization specific routines from the legacy code.

Use of jstack-review¶

This is a free tool written exclusively in JS and can be cloned from https://github.com/jstack-review/jstack-review. It doesn't require any installation and runs directly in the browser.

Logs interpretation¶

FWD has a solid infrastructure in terms of logging that can be configured. A standard configuration may include only WARNING and SEVERE logs with only a few INFO on some packages. However, development teams can troubleshoot issues by lowering the logging level (i.e. to FINE, FINER or FINEST) and replicate the issue. This way, most context is provided at the moment when the problem occurs. In production, logs are not that granular, but still can report SEVERE issues that trigger exceptions. In fact, the first point of contact with an problem diagnosis should be the log file.

What to look for in a server log¶

First thing to look for is a Java exception. Not always the exceptions are fatal, but the ones logged by FWD are usually a matter of concern. FWD will attempt to recover from such failure but rollbacking current transactions, UNDO variables, etc. (just like legacy system do in case of errors). Eventually, the session will crash if the recovery wasn't fully possible, but the server will stay alive.

Exceptions printed usually hint internal issues and not business logic errors (that can be managed by legacy ON ERROR or CATCH). Thus, it is most often a problem from within FWD or a misconfiguration of the server that lead to unexpected behavior (i.e. Java version mismatch, wrong classpath, etc.).

Use of Eclipse MAT¶

Comparing to thread-dumps that are rather small text-based files, heap dumps can be very large (tens of GB) and require special tools to be interpreted. For that matter, Eclipse MAT (https://eclipse.dev/mat/) is recommended for heap dump analysis. After download, it can load memory dumps in a couple of minutes, provided that it is properly configured to support heap dumps of large sizes. For that, the MemoryAnalyzer.ini file should be configured to use the right -Xmx enough to load the heap dump. This should usually match the Xmx provided to the FWD server.

After loading the heap dump for the first time, the artifacts for interpretation are saved on disk, so that the second load of the same dump will take way less time (couple of seconds).

Overview¶

First thing displayed by the Eclipse MAT is the automatically interpreted overview of the heap dump provided. Usually, the biggest part is represented by the Remainder which is basically the accumulation of data that couldn't be grouped into a big relevant chunk.

SourceNameMapper: is an internal FWD class that handled the mapping between legacy names (procedures, methods, classes, functions, etc.) and may occur in the overview. This is no reason to get nervous because it is usually meant to hold ~1GB of the heap.
ProcedureManager$WorkArea: these are classes specific to a session's control flow. Usually, the state of a session is hold by a WorkArea object. Thus, seeing this in the overview means that there is a lot of control flow (i.e. block stack) data stored per session, which is usually OK, as long as it doesn't exceed a couple of GB.
- Other TransactionManager, ProcedureManager or ControlFlowOps specific objects may be presented here with the same goal.
LogicalTerminal, ServerConfigManager, WidgetConfigDef, *Widget are specific to the UI part of the application. Complex screens displayed to multiple sessions may accumulate on the server, but closing such screens results in memory free-up. Technically, the UI stuff per-session, so the more complex the screen is, the more memory is requried on the server side to store the state.
h2 specific classes are hinting to H2 technology used for _temp database. High retaining data there means a lot of memory is engaged into storing temporary data. This can be usually big in demanding business logic cases and can get to a couple of GB across all sessions.
- similarly postgresql (or other database vendor) packages represent memory engaged in communication with external databases. These shouldn't be that big because the data per-se is not stored in memory. Usually these values get high when retrieving really large ResultSet instances.
maybe other ...

One should look for a big object that pins more than 1GB of the memory and is not something expected: a temporary table content, a query result-set, a JSON/XML document, etc. If that is the case, it means that the server might have incorrectly run the converted code and ended up accumulating data or there is a bug internal run-time that caused a lot of memory consumption.

Another important aspect to consider is whether the big objects are per server or per client. If they are per client, then killing a session will eventually clear up the memory. It might be a case in which a client requested a very demanding task that required a lot of memory in the process. However, one can cross-check the thread dumps to understand whether this is an infinite loop or a long running process. Otherwise, if the objects are per server, then it is a big issue. It means that the server might slowly retain data and eventually crash - this is not desired.

On the other note, memory can increase over time without actually being a memory leak. This is because FWD has sometimes really large caches that are filled very slow. Maybe after hours/days of functioning, the maximum size of the caches are hit so that the expected accumulation ends. In other words, increase in old gen memory across hours is not always a memory leak.

Leak suspects¶

The leak suspects report represents a tool that enabled Eclipse MAT to tell if there is any potential memory leak in the application. This is not always a guarantee memory leak, but a hint on a possible one. Eclipse MAT analyses very big collections pretending that data has slowly accumulating in it. However, FWD specific structures and cached might have such behavior, tricking MAT into thinking that it is a memory leak. Some FWD technology knowledge is required to tell if a reported memory leak is in fact concerning or not:

Class instance is usually reported in the memory leak report because static marked resources are kept at Class level. This means that any collection / cache that is static (i.e. across sessions) is retained by the Class / ClassLoader, making it appear as a memory leak. In reality, these are only server level collections / caches that tend to be quite big. This is not usually a matter of concern.
other ...

Dominator Tree¶

This can be activated by using the Dominator tree button in the toolbar. This is the main view on all objects in the memory. It is built around the Retained Heap metric. Resources can be grouped on packages, objects, class loader or classes. The most common ordering is per package as it visually groups them similarly to the file-system. In this view, one can distinguish the retained memory of customer specific instances vs FWD specific instances:

DMOs: a good hint on memory consumption are the DMOs that can be found in the customer specific package. The count of such objects is relevant as it may hint that too many records of a certain table are loaded in memory at once. Having at most 1.000 - 10.000 DMOs might be a good statistic to check if the count is normal. Bypassing 10.000 DMOs of the same kind may hint a malfunction (i.e. a query storing too much data in memory, a cache that gets to big, etc.).
FWD specific collections: these require FWD knowledge to understand whether they are meant to be that big or not. For example:
- FastFindCache: stores information about FIND queries and their results. It is cross-session for persistent databases and intra-session for temporary databases. After multiple hours of server usage, this can reach at accumulated size of 1GB.
- DmoMeta, Property, RecordMeta: there is one such class per DMO / property and stores information about that. Once all DMOs are loaded, we may end up with thousands of such instances with an accumulated size of 200MB.
other ...

Incoming/Outcoming references¶

Using right-click, one can toggle other views that are relevant for the selected class. For instance, one can detect all paths from the GC root that retain that object (Merge Shortest Paths to GC root > exclude all phantom / weak / soft references). This way, the threads that actually hold onto records of that specific object will be shown. That means that we can see ChUI/GUI clients, appservers or batch processes that hold onto different instances of the requested class and the distribution of such objects across that sessions. This is also a moment when the user of MAT can detect if the objects are per client / per server / both. Ideally, session specific classes should be referenced only by threads that are session specific, while server-level instances should be referenced only by server-wide threads (including class-loader). Server-level objects that are also part of client threads should have been eventually locked as they are available cross-session.

Project

General

Profile

FWD

Wiki