uCosminexus Application Server, Maintenance and Migration Guide

[Contents][Glossary][Index][Back][Next]

5.11.4 Contents output when output level is verbose

This subsection describes the contents output for each event when you specify verbose in the log output level. Verbose is a log output level to output detail information required for the error analysis.

Supplement
In verbose, besides contents output for normal, detail log is output for contents that are not output in normal. The log output would cost some overheads and there might be the degradation in throughput, if verbose is specified for normal operations.
Organization of this subsection
(1) Initialization of Explicit memory block
(2) Initialization failure of Explicit memory block
(3) Disable of sub status of Explicit memory block
(4) Object generation to Explicit memory block
(5) Moving to Explicit memory block (Output detail information)
(6) Explicit memory block explicit release process (Output detail information)
(7) Release reservation of Explicit memory block by finalize
(8) Automatic allocation to Explicit Memory Management

(1) Initialization of Explicit memory block

When you initialize the Explicit memory block newly, the name, ID and type of initialized Explicit memory block is output.

(a) Output trigger

Initialization of Explicit memory block.

(b) Output format
[EVO]<ctime>[Created]["<EM_NAME>" eid=<EID>(<EM_PTR>)/<EM_TYPE>]
(c) Output items

The following table describes each item indicated in (b) output trigger.

Table 5-44 Output items (Initialization of Explicit memory block)

Output items Output contents Meaning
<ctime> <letters> Indicates the date and time on which Explicit memory block was initialized. Output in the format same as extended verbosegc information.
Output in milli-seconds unit when -XX:+HitachiOutputMilliTime option is set.
<EM_NAME> <letters> Output name of initialized Explicit memory block.
The output contents are uncertain when multi byte characters are included in name of Explicit memory block (Usually garbled and output).
<EID> <const> Output ID of initialized Explicit memory block.
<EM_PTR> <ptr> Output value that indicates internal status of Explicit memory block.
<EM_TYPE> R|B Output type of initialized Explicit memory block.
R indicates Explicit memory block used internally in Application Server. B indicates the type of the Explicit memory block in JavaVM.
(d) Example of output

Output example:

[EVO]<Tue Jul 24 01:23:51 2007>[Created]["BasicExplicitMemory-2" eid=2(0x1234568)/B]

You can confirm the following contents in this output example:

(2) Initialization failure of Explicit memory block

Output when an attempt to initialize Explicit memory block failed while initializing Explicit memory block. The cause for failure is that the Explicit memory blocks have reached the maximum count. Output the number of Explicit memory blocks and stack trace of Java program that failed in initialization.

This log is output on multiple lines. This log is output asynchronously with the execution of the Java program. Hence, there are cases when some other log is output within the lines of this log. However, other logs are not output within one line.

(a) Output trigger

The output is triggered when Explicit memory block reaches the upper limit of Explicit memory blocks and when an attempt to initialize the Explicit memory block fails.

(b) Output format
[EVO]<ctime>[Creation failed][EH: <EH_USED>(<EH_GARB>)/<EH_TOTAL>/<EH_MAX>][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>][Thread: <TH_PTR>]
[EVO][Thread: <TH_PTR>] at <FRAME><SOURCE>
...
(c) Output items

The following table describes each item indicated in (b) output trigger.

Table 5-45 Output contents (Initialization failure of Explicit memory block)

Output items Output contents Meaning
<ctime> <letters> Indicates failure date and time of initialization of Explicit memory block. Output in the format same as extended verbosegc information.
Output in milli-seconds unit when -XX:+HitachiOutputMilliTime option is set.
<EH_USED> <const>K Output used size of Explicit heap when failed in initialization of Explicit memory block. The unit is kilo bytes.
<EH_GARB> <const>K The internal status of Explicit heap is output.
<EH_TOTAL> <const>K Output secured size of Explicit heap when failed in initialization of Explicit memory block. The unit is kilo bytes.
<EH_MAX> <const>K Output Explicit heap maximum size. The unit is kilo bytes.
<AC_NUM> <const> Output number of Explicit memory blocks whose sub status is Enable when failed in initialization of Explicit memory block.
<FL_NUM> <const> Normally 0 is output
<DA_NUM> <const> Output number of Explicit memory blocks whose sub status is Disable when failed in initialization of Explicit memory block.
<TH_PTR> <ptr> Output thread ID of threads failed in initialization of Explicit memory block. Thread ID is same as tid output to thread dump.
<FRAME> <letters>.<letters> Output one frame in stack trace when failed in initialization of Explicit memory block. Output all class names and method names by delimiting them by a ".".
<SOURCE> (<letters>:<const>)|(Native Method)|(Unknown Source) Output the source file names where methods output to <FRAME> are described and the line numbers match the stack trace. Output the file name and line numbers by delimiting them by a ":".
Output as "(Native Method)" for native method. Output as "(Unknown Source)" when you cannot acquire source file name.
(d) Example of output

Output example.

[EVO]<Tue Jul 24 01:23:51 2007>[Creation failed][EH: 12000K(0K)/15000K/30000K][E/F/D: 65535/0/0][Thread: 0x00035a60]
[EVO][Thread: 0x00035a60] at ExplicitMemory.registerExplicitMemory(Native Method)
[EVO][Thread: 0x00035a60] at BasicExplicitMemory.<init>(Unknown Source)
[EVO][Thread: 0x00035a60] at AllocTest.test(AllocTest.java:64)
[EVO][Thread: 0x00035a60] at java.lang.Thread.run(Thread.java:2312)

You can confirm the following contents in this output example:

(3) Disable of sub status of Explicit memory block

Output the information of Explicit memory block in which the usage status and sub status are changed to Disable, when the sub status of Explicit memory block is changed to Disable. This log is output on multiple lines and output asynchronously with the execution of Java program. Hence, there are cases where some other log is output within the lines of this log. However, other logs are not output within one line.

(a) Output trigger

Output is triggered when sub status of Explicit memory block is Disable and when you cannot map the object to respective Explicit memory block.

(b) Output format
[EVO]<ctime>[Alloc failed(Disable)][EH: <EH_USED>(<EH_GARB>)/<EH_TOTAL>/<EH_MAX>][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>][cause:<CAUSE>]\
["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_USED>(<EM_GARB>)/<EM_TOTAL>][Thread: <TH_PTR>]
[EVO][Thread: <TH_PTR>] at <FRAME><SOURCE>
...

#
The Underlined part is output only for New.

(c) Output items

The following table describes each item indicated in (b) output trigger.

Table 5-46 Output items (Disable sub status of Explicit memory block)

Output items Output contents Meaning
<ctime> <letters> Indicates the date and time when sub status of Explicit memory block with <EID> is changed to Disable. Output in the format same as extended verbosegc information.
Output in milli-seconds unit when -XX:+HitachiOutputMilliTime option is set.
<EH_USED> <const>K Output used size of Explicit heap when sub status of Explicit memory block with <EID> is Disable. The unit is kilo bytes.
<EH_GARB> <const>K Output value indicating internal status of Explicit heap.
<EH_TOTAL> <const>K Output secured size of Explicit heap when sub status of Explicit memory block with <EID> is Disable. The unit is kilo bytes.
<EH_MAX> <const>K Output Explicit heap maximum size. The unit is kilo bytes.
<AC_NUM> <const> Output number of Explicit memory blocks that are Enable after changing the sub status of Explicit memory block with <EID> to Disable.
<FL_NUM> <const> Normally 0 is output
<DA_NUM> <const> Output number of Explicit memory blocks that whose sub status is Disable after changing the sub status of Explicit memory block with <EID> to Disable.
<CAUSE> New|GC|Full GC Output the process that cause Disable of sub status.
The output contents and measures for the cause are as follows:
  • "New"
    The cause is direct generation of object in Explicit heap by newInstance().
  • "GC"
    The cause is moving the object to Explicit heap by copy garbage collection.
  • "Full GC"
    The cause is moving the object to Explicit heap by full garbage collection.
<EM_NAME> <letters> Output name of Explicit memory block whose sub status is Disable.
The output contents are uncertain when multi byte characters are included in name of Explicit memory block (Usually garbled and output).
<EID> <const> Output ID of Explicit memory block whose sub status is Disable.
<EM_TYPE> R|B|A Output type of Explicit memory block whose sub status is Disable.
R indicates Explicit memory block used internally in Application Server. B indicates the type of the Explicit memory block in JavaVM. A indicates the Explicit memory block specified using the automatic allocation configuration file.
<EM_USED> <const>K Output used size of Explicit memory block whose sub status is Disable. The unit is kilo bytes.
<EM_GARB> <const>K Output value indicating internal status of Explicit memory block.
<EM_TOTAL> <const>K Output secured size of Explicit memory block whose sub status is Disable. The unit is kilo bytes.
<TH_PTR> <ptr> Output thread ID of thread executing object generation to Explicit heap as the sub status is Disable. Thread ID is same as the tid output to thread dump.
This item is output only when <CAUSE> is "New".
<FRAME> <letters>.<letters> Output one frame in stack trace output as a result of direct object generation when sub status is Disable due to direct object generation in Explicit heap.
Output all class names and method names by delimiting them by a ".".
This item is output only when <CAUSE> is "New".
<SOURCE> (<letters>:<const>)|(Native Method)|(Unknown Source) Output the source file names where methods output to <FRAME> are described and the line numbers that match the stack trace. Output the file name and line numbers by delimiting them by a ":".
Output as "(Native Method)" for native method. Output as "(Unknown Source)" when you cannot acquire source file name.
This item is output only when <CAUSE> is "New".
(d) Example of output

Output example.

[EVO]<Tue Jul 24 01:23:51 2007>[Alloc failed(Disable)][EH: 12000K(1258K)/15000K/30000K][E/F/D: 321/0/1][cause:GC]\
["ReferenceExplicitMemory-3" eid=3/R: 108K(20K)/108K]

You can confirm the following contents in this output example:

(4) Object generation to Explicit memory block

Output when object is generated directly in Explicit memory block using ExplicitMemory.newInstance().

(a) Output trigger

Output is triggered when object is generated in Explicit memory block.

(b) Output format
[EVS]<ctime>[EH: <EH_USED_BF>-><EH_USED_AF>(<EH_TOTAL>/<EH_MAX>)][E/F/D: <AC_NUM>/<FL_NUM>/<DA_NUM>][cause:<CAUSE>]\
["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_USED_BF>-><EM_USED_AF>(<EM_TOTAL>)]
(c) Output items

The following table describes each item indicated in (b) output trigger.

Table 5-47 Output items (Object generation to Explicit memory block)

Output items Output contents Meaning
<ctime> <letters> Indicates the date and time when object is generated in Explicit memory block. Output in the format same as extended verbosegc information.
Output in milli-seconds unit when -XX:+HitachiOutputMilliTime option is set.
<EH_USED_BF> <const>K Output used size of Explicit heap before object generation. The unit is kilo bytes.
<EH_USED_AF> <const>K Output used size of Explicit heap after object generation. The unit is kilo bytes.
<EH_TOTAL> <const>K Output secured size of Explicit heap after object generation. The unit is kilo bytes.
<EH_MAX> <const>K Output maximum size of Explicit heap. The unit is kilo bytes.
<AC_NUM> <const> Output the number of Explicit memory blocks whose sub status is Enable after object generation.
<FL_NUM> <const> Normally 0 is output
<DA_NUM> <const> Output number of Explicit memory blocks whose sub status is Disable after object generation.
<CAUSE> New Always output as "New".
Indicates that migration of object to Explicit memory block is executed from Java program.
<EM_NAME> <letters> Output name of Explicit memory block where object is generated.
The output contents are uncertain when multi byte characters are included in name of Explicit memory block (Usually garbled and output).
<EID> <const> Output ID of Explicit memory block where object is generated.
<EM_TYPE> R|B|A Output type of Explicit memory block where object is generated.
R indicates Explicit memory block used internally in Application Server. B indicates the type of the Explicit memory block in JavaVM. A indicates the Explicit memory block specified using the automatic allocation configuration file.
<EM_USED_BF> <const>K Output used size of Explicit memory block that is generation destination before object generation. The unit is kilo bytes.
<EM_USED_AF> <const>K Output used size of Explicit memory block that is generation destination after object generation. The unit is kilo bytes.
<EM_TOTAL> <const>K Output secured size of Explicit memory block that is generation destination after object generation. The unit is kilo bytes.
(d) Example of output

Output example.

[EVS]<Thu Oct 21 14:55:50 2007>[EH: 150528K->150529K(150532K/1048576K)][E/F/D: 200/0/0][cause:New]["BEM" eid=2/B: 30K->31K(32K)]

You can confirm the following contents in this output example:

(5) Moving to Explicit memory block (Output detail information)

Output detail information for moving object to Explicit memory block. Besides the output contents described in 5.11.3(1) Garbage collection occurrence (Output Explicit heap usage status), output the usage status of all Explicit memory blocks where the objects are to be moved.

(a) Output trigger

Output is triggered when object moves to Explicit memory block as a result of occurrence of garbage collection.

(b) Output format
<Explicit heap usage status when garbage collection occurred>#
[EVS]{["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_USED_BF>-><EM_USED_AF>(<EM_TOTAL>)]}{1,5}
...

Note:
Linefeed information of Explicit memory block after output of every five blocks.

#
For output items, see 5.11.3(1) Garbage collection occurrence (Output Explicit heap usage status).

(c) Output items

The following table describes each item indicated in (b) output trigger.

Table 5-48 Output items (Moving to Explicit memory block (Output detail information))

Output items Output contents Meaning
Explicit heap usage status when garbage collection occurred See 5.11.3(1) Garbage collection occurrence (Output Explicit heap usage status).
<EM_NAME> <letters> Output name of Explicit memory block where the object is to be moved when garbage collection occurred.
The output contents are uncertain when multi byte characters are included in name of Explicit memory block (Usually garbled and output).
<EID> <const> Output ID of Explicit memory block where the object is to be moved when garbage collection occurred.
<EM_TYPE> R|A Output type of Explicit memory block where the object is to be moved when garbage collection occurred.
R or A is output. R indicates the type of the Explicit memory block in JavaVM. A indicates the Explicit memory block specified by using the automatic allocation configuration file.
<EM_USED_BF> <const>K Output used size before occurrence of garbage collection of Explicit memory block where the object is to be moved when garbage collection occurred. The unit is kilo bytes.
<EM_USED_AF> <const>K Output used size after occurrence of garbage collection of Explicit memory block where the object is to be moved when garbage collection occurred. The unit is kilo bytes.
<EM_TOTAL> <const>K Output secured size after occurrence of garbage collection of Explicit memory block where the object is to be moved when garbage collection occurred. The unit is kilo bytes.
(d) Example of output

Output example.

[ENS]<Thu Oct 21 14:55:50 2007>[EH: 150528K->162816K(162816K/1048576K)][E/F/D: 200/0/0][cause:GC][CF: 0]
[EVS]["REM2" eid=2/R: 0K->88K(128K)]["REM3" eid=3/R: 30K->230K(256K)]["REM6" eid=6/R: 30K->2030K(2048K)]\
["Session1" eid=8/R: 30K->2530K(2548K)]["Session2" eid=10/R: 30K->2530K(2548K)]
[EVS]["Session3" eid=12/R: 30K->5030K(5048K)]

You can confirm the following contents in this output example:

(6) Explicit memory block explicit release process (Output detail information)

Output detail information when the explicit release process of Explicit memory block occurred. Besides the contents output to 5.11.3(2) Explicit memory block explicit release process, output the information of all the explicitly released Explicit memory blocks.

While explicitly releasing the Explicit memory block, if there is a Java heap overflow, output the information by adding information of Explicit memory blocks explicitly released before overflow. The information described here is not output to the output contents of 5.11.3(3) Java heap overflow in Explicit memory block explicit release process.

(a) Output trigger

The Explicit release process of Explicit memory block.

(b) Output format
<Explicit memory block explicit release process>#
[EVS]{["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_TOTAL>]}{1,5}
...

Note:
Linefeed information of Explicit memory block after every five blocks.

#
For details on the output item, see 5.11.3(2) Explicit memory block explicit release process.

(c) Output items

The following table describes each item indicated in (b) output trigger.

Table 5-49 Output items (Explicit memory block explicit release process (Output detail information))

Output items Output contents Meaning
Information output by release process of Explicit memory block See 5.11.3(2) Explicit memory block explicit release process.
<EM_NAME> <letters> Output name of the explicitly released Explicit memory block.
The output contents are uncertain when multi byte characters are included in name of Explicit memory block (Usually garbled and output).
<EID> <const> Output ID of the explicitly released Explicit memory blocks.
<EM_TYPE> R|B|A Output type of the explicitly released Explicit memory blocks.
R indicates Explicit memory block used internally in Application Server. B indicates the type of the Explicit memory block in JavaVM. A indicates the Explicit memory block specified using the automatic allocation configuration file.
<EM_TOTAL> <const>K Output secured memory size (memory size released explicitly in the explicit release process) of the explicitly released Explicit memory blocks. The unit is kilo bytes.
(d) Example of output

Output example.

[ENS]<Tue Jul 24 01:23:51 2007>[EH: 150528K->149528K(162816K/1048576K), 0.1129602 secs][E/F/D: 523/0/0]\
[DefNew::Eden: 0K->0K(243600K)][DefNew::Survivor: 0K->0K(17400K)][Tenured: 103400K->103400K(556800K)][cause:Reclaim]
[EVS]["REM2" eid=3/R: 300K]["BEM3" eid=5/B: 300K]["BEM1" eid=7/B: 400K]

You can confirm the following contents in this output example:

(7) Release reservation of Explicit memory block by finalize

Output when an Explicit memory block corresponding to the finalize method of the ExplicitMemory class is reserved for release as a result of the disconnection of a reference to an ExplicitMemory instance.

(a) Output trigger

Output is triggered when release of Explicit memory block is reserved by ExplicitMemory.finalize() method.

(b) Output format
[EVO]<ctime>[Finalized]["<EM_NAME>" eid=<EID>/<EM_TYPE>: <EM_TOTAL>]
(c) Output items

The following table describes each item indicated in (b) output trigger.

Table 5-50 Output items (Release reservation of Explicit memory block by finalize)

Output items Output contents Meaning
<ctime> <letters> Indicates the reserved date and time for release. Output in the format same as extended verbosegc information.
Output in milli-seconds unit when -XX:+HitachiOutputMilliTime option is set.
<EM_NAME> <letters> Output name of Explicit memory block reserved for release.
The output contents are uncertain when multi byte characters are included in name of Explicit memory block (Usually garbled and output).
<EID> <const> Output ID of Explicit memory block reserved for release.
<EM_TYPE> B Output type of Explicit memory block reserved for release.
B indicates the type of the Explicit memory block in JavaVM. Indicates Explicit memory block used by the application if Application Server version is earlier than 08-50.
<EM_TOTAL> <const>K Output size secured (Memory size released by release process) by Explicit memory blocks reserved for release. The unit is kilo bytes.
(d) Example of output

Output example.

[EVO]<Tue Jul 24 01:23:51 2007>[Finalized]["REM1" eid=3/R: 512K]

You can confirm the following contents in this output example:

(8) Automatic allocation to Explicit Memory Management

A log message is output, when the specified class succeeds in automatic allocation to Explicit Memory Management.

(a) Output trigger

The log message is output, when the specified class succeeds in automatic allocation to Explicit Memory Management.

(b) Output format
[EVA]<ctime> creation in explicit memory is succeeded. [class=<CLASSNAME>]
(c) Output items

The following table describes the items specified in (b) Output format.

Table 5-51 Output items (Automatic allocation to Explicit Memory Management)

Output items Output contents Meaning
<ctime> <letters> Indicates the occurrence time when the specified class succeeded in automatic allocation to Explicit Memory Management. Output with the format same as would output for the extended verboseGC functionality. Output in milliseconds, when the HitachiOutputMilliTime option is set.
<CLASSNAME> <letters> Outputs the fully qualified class name of the class that succeeded in automatic allocation to Explicit Memory Management.
(d) Example of output

An output example is as follows:

[EVA]<Tue Jul 24 01:23:51 2007> creation in explicit memory is succeeded. [class=jp.co.sample.Main]

You can check the following details in this output example: