PowerCenter mapping fails on writing to Vertica

Serge_Larionoff_1

Dear colleagues!

I have ~50 similar simple mappings which load data from Oracle to Vertica. There are only 4 transformations in mapping - Source, Source Qualifier (without any filters, joins etc), Target (of Vertica type) and Expression (just to add some technical fields - Workflow run ID, Processing date etc). So, problem is the following: most of mappings work fine, they load data fast and without errors. But one workflow always fails with following error lines:


Severity Timestamp Node Thread Message Code Message
ERROR 26.08.2014 9:36:29 node01_nhd-etl WRITER_1_*_1 SDKS_38502 Plug-in #445050's target [DOCUMENTS: Partition 1] failed in method [execute].
INFO 26.08.2014 9:36:29 node01_nhd-etl WRITER_1_*_1 WRT_8333 Rolling back all the targets due to fatal session error.
INFO 26.08.2014 9:36:41 node01_nhd-etl WRITER_1_*_1 VERTICA_3083 [INFO] Starting Rollback Transaction
ERROR 26.08.2014 9:37:02 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR] java.lang.OutOfMemoryError: GC overhead limit exceededjava.lang.OutOfMemoryError: GC overhead limit exceeded
ERROR 26.08.2014 9:37:12 node01_nhd-etl WRITER_1_*_1 WRT_8183 Rollback failed for the target [sc_DOCUMENTS]
ERROR 26.08.2014 9:37:12 node01_nhd-etl WRITER_1_*_1 WRT_8081 Writer run terminated. [Error in loading data to target table [DOCUMENTS: Partition 1]]
INFO 26.08.2014 9:37:12 node01_nhd-etl WRITER_1_*_1 WRT_8168 End loading table [DOCUMENTS: Partition 1] at: Tue Aug 26 16:37:11 2014
ERROR 26.08.2014 9:37:33 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR] Cannot close connection: [Vertica][JDBC](11380) Null pointer exception.
ERROR 26.08.2014 9:37:33 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at com.vertica.informatica.powerconnect.server.writer.VerticaWriterPartitionDriver.deinit(Unknown Source)
ERROR 26.08.2014 9:37:33 node01_nhd-etl WRITER_1_*_1 SDKS_38502 Plug-in #445050's target [DOCUMENTS: Partition 1] failed in method [deinit].


and rest of the log is filled with repeating lines like:


[ERROR]     at com.vertica.jdbc.common.SPreparedStatement.clearBatch(Unknown Source)
[ERROR]     at com.vertica.jdbc.VerticaJdbc4PreparedStatementImpl.clearBatch(Unknown Source)
[ERROR]     at com.vertica.jdbc.common.SPreparedStatement.close(Unknown Source)
[ERROR]     at com.vertica.jdbc.common.SStatement.checkIfOpen(Unknown Source)
...

ERROR 26.08.2014 9:37:37 node01_nhd-etl TRANSF_1_1_1 TM_6085 A fatal error occurred at  transformation [sc_DOCUMENTS], and the session is terminating.
ERROR 26.08.2014 9:37:37 node01_nhd-etl TRANSF_1_1_1 TM_6085 A fatal error occurred at  transformation [exp_MAIN], and the session is terminating.
ERROR 26.08.2014 9:37:37 node01_nhd-etl TRANSF_1_1_1 TM_6085 A fatal error occurred at  transformation [exp_MAIN], and the session is terminating.
ERROR 26.08.2014 9:37:37 node01_nhd-etl TRANSF_1_1_1 TM_6085 A fatal error occurred at  transformation [SQ_sc_DOCUMENTS], and the session is terminating.
ERROR 26.08.2014 9:37:37 node01_nhd-etl TRANSF_1_1_1 TM_6085 A fatal error occurred at  transformation [SQ_sc_DOCUMENTS], and the session is terminating.
ERROR 26.08.2014 9:37:37 node01_nhd-etl TRANSF_1_1_1 TM_6085 A fatal error occurred at  transformation [SQ_sc_DOCUMENTS], and the session is terminating.
DEBUG 26.08.2014 9:37:37 node01_nhd-etl TRANSF_1_1_1 DBG_21511 TE: Fatal Transformation Error.


I have read this community, PDF about Vertica plugin to PowerCenter, but all wisdom I took from those sources didn't help me. So I would like to ask - what should I do to make my mappings work more stable?

Thanks in advance!

eli_revach

I see  java hip size issue - > java.lang.OutOfMemoryError: GC overhead limit exceededjava.lang.OutOfMemoryError: GC overhead limit exceeded .
 do you try to increases memory setting of you JVM  ? 

Serge_Larionoff_1

Hi Eli Revach!
Yes, I did as it is written in PDF (unfortunately I didn't find how to attach the whole log, so I didn't placed this information in first message). Please find lines from log below:

Severity Timestamp Node Thread Message Code Message
INFO 26.08.2014 9:29:25 node01_nhd-etl DIRECTOR TM_6708 Using configuration property [JVM1,-Xmx=1024m]
INFO 26.08.2014 9:29:25 node01_nhd-etl DIRECTOR TM_6708 Using configuration property [JVM2,-Xmx=2048m]
INFO 26.08.2014 9:29:25 node01_nhd-etl DIRECTOR TM_6708 Using configuration property [maximum_heap_memory,-Xmx=4096m]
INFO 26.08.2014 9:29:25 node01_nhd-etl DIRECTOR TM_6708 Using configuration property [minimum_heap_memory,-Xms=1024m]

eli_revach

You need to check what Is different on this mapping that its different for others , are its related to amount of process data ( its behave  different when  you process small chunks ) ? different logic  , different target table that may include many more columns that the others and etc 

Serge_Larionoff_1

Eli, the worst thing is that mapping is not somethng outstanding, it is just average between others. There are mappings with more fields, bigger tables, they work fine, but this doesn't. I created all of them in one peace using special Informatica serializing tool, Mapping Architect for Visio, so all the logic is comletely the same in the whole batch of mappings.

About chunks - all sessions has a default commit interval in 10'000 records. I tested my problem session with increased interval in 1'000'000 records with no result.

I had one idea today morning - source data (Oracle) contains varchar2 field and I know for sure that there are some formatting characters in one record (I mean CR+LF). But even when I replaced those symbols to plain text it didn't help. So now I have no more ideas yet.

eli_revach

Try to check your mapping when your data source is  diffrent  each time for ex :
1K , 10K and 100K records , do you see diffrent behave ?

Serge_Larionoff_1

Do you mean the number of source records or commit interval?

Daniel_Leybovic

Hi Serge!

Im agree with Eli - the problem in JVM configuration. I suggest you to use in VisualVM (java troubleshooting tool) to locate your problem.

Serge_Larionoff_1

Eli, at least ability of work of this mapping depends on amount of input records. There is a threshold (around 550'000 records, commit interval now is still 1'000'000) and if I try to process too many records then session fails. But error message differs from previous one and now it is:

Severity Timestamp Node Thread Message Code Message
ERROR 26.08.2014 14:50:56 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR] java.lang.OutOfMemoryError: Java heap space
ERROR 26.08.2014 14:51:11 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at java.util.TreeMap.buildFromSorted(TreeMap.java:2384)
ERROR 26.08.2014 14:51:19 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at java.util.TreeMap.buildFromSorted(TreeMap.java:2396)
ERROR 26.08.2014 14:51:35 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at java.util.TreeMap.buildFromSorted(TreeMap.java:2322)
ERROR 26.08.2014 14:51:43 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at java.util.TreeMap.putAll(TreeMap.java:296)
ERROR 26.08.2014 14:51:59 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at java.util.TreeMap.<init>(TreeMap.java:162)
ERROR 26.08.2014 14:52:07 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at com.vertica.jdbc.common.SPreparedStatement.addBatch(Unknown Source)
ERROR 26.08.2014 14:52:23 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at com.vertica.informatica.powerconnect.server.writer.VerticaWriterPartitionDriver.execInsert(Unknown Source)
ERROR 26.08.2014 14:52:39 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at com.vertica.informatica.powerconnect.server.writer.VerticaWriterPartitionDriver.execute(Unknown Source)
ERROR 26.08.2014 14:52:39 node01_nhd-etl WRITER_1_*_1 SDKS_38502 Plug-in #445050's target [DOCUMENTS: Partition 1] failed in method [execute].
INFO 26.08.2014 14:52:39 node01_nhd-etl WRITER_1_*_1 WRT_8333 Rolling back all the targets due to fatal session error.
INFO 26.08.2014 14:52:47 node01_nhd-etl WRITER_1_*_1 VERTICA_3083 [INFO] Starting Rollback Transaction
ERROR 26.08.2014 14:53:20 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR] java.lang.OutOfMemoryError: Java heap space
ERROR 26.08.2014 14:53:43 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at java.util.Hashtable.put(Hashtable.java:420)
ERROR 26.08.2014 14:53:59 node01_nhd-etl WRITER_1_*_1 WRT_8183 Rollback failed for the target [sc_DOCUMENTS]
ERROR 26.08.2014 14:53:59 node01_nhd-etl WRITER_1_*_1 WRT_8081 Writer run terminated. [Error in loading data to target table [DOCUMENTS: Partition 1]]
INFO 26.08.2014 14:53:59 node01_nhd-etl WRITER_1_*_1 WRT_8168 End loading table [DOCUMENTS: Partition 1] at: Tue Aug 26 21:53:58 2014
ERROR 26.08.2014 14:55:01 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR] java.lang.OutOfMemoryError: Java heap space
ERROR 26.08.2014 14:55:45 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at java.lang.String.toCharArray(String.java:2725)

Serge_Larionoff_1

Hi Daniel! Thank you fo responce! Is there any short instruction for dumbs on this VisualVM?

Serge_Larionoff_1

Actually, I don't get how can I place this software between to proprietary software products, IPC and Vertica.

eli_revach

Source records 

Serge_Larionoff_1

OK, I tried to vary this amoint and there is a dependency exists but it is not stable and sometimes 700'000 records will be written to DB and sometimes not.

Is there any kind of log on the Vertica side in which I could find detailed information on what went wrong during operation? I didn't find any. Could a Vertica Console software help me?

[Deleted User]

Thanks Eli and Daniel for the responses here!

If I may answer a Vertica-specific question:  There are Vertica logs; see the "vertica.log" file in the catalog directory of the node that you have connected to.  Vertica's Management Console also displays lots of cluster-health information.  But, fundamentally, this is a Java error, and the core server is a native (not Java) application.  So Vertica-server logs are, I think, unlikely to help.

One question -- I assume PowerCenter is using the Vertica JDBC driver?  What version of the driver is it using?  (Does the latest driver work any better?)  Also, when PowerCenter is loading data, what is its batch size?

There was a period of time when the Vertica JDBC driver kept all of each batch in memory.  ("batch" at the JDBC prepared-statement level -- there can, and normally should be, many batches per data load.)  If a client program had an unreasonably-large batch size, this could exhaust the Java heap and produce this error.  Recent drivers no longer have this limitation by default; batches are managed on the server side, where we have more flexibility.

Adam

Daniel_Leybovic

Hi!


Do you tried to release java memory between commits?

If the jvm memory pool is depleted, queries containing Java UDxs either block until memory becomes available or eventually fail due a lack of resources. If you find queries blocking or failing for this reason, you can allocate more memory to the jvm pool and increase its PLANNEDCONCURRENCY. Another option is to ask users to call the RELEASE_JVM_MEMORY function when they no longer need to run Java UDxs. This function closes any JVM belonging to the user's session and returns its allocated memory to the jvm memory pool.

=========================
You can try to force GC. Someone said me it can help, but I do not trust on it.
http://stackoverflow.com/questions/1481178/forcing-garbage-collection-in-java
http://www.programcreek.com/2011/07/system-gc/
=========================

is there any short instruction for dumbs on this VisualVM?

Sorry, profiling its a separate and complex theme. My English doesn't allow me to explain it. I will try to find a time and may be will do a short video how to profile JDBC/JUDF, but I belive Vertica will improve it Documentation and profiling will be explained.  Take in mind Vertica is very "young" product and if you will review docs now, so you will find how to develop on Eclipse for example. Very nice, i like it.
(Holywar - Eclipse must die, Intellij Idea rules).
=========================

Actually, I don't get how can I place this software between to proprietary software products, IPC and Vertica.

You don't need. Read docs for VisualVM:

VisualVM provides detailed information about Java applications while they are running on the Java Virutal Machine (JVM). VisualVM's graphical user interface enables you to quickly and easily see information about multiple Java applications.

So install desktop (GUI) + VisualVM on your TEST/DEV environment, with same configarion for JVM as on PROD environment, run your Java application and profile with VisualVM.  VisualVM will show you detailed information about what happens inside of JVM

https://www.youtube.com/watch?v=z8n7Bg7-A4I
https://www.youtube.com/watch?v=Bjv_9pKiALQ
https://www.youtube.com/watch?v=pRwvx4QpUfo
=========================
As option you can write your own profiler with Java:

• http://www.rapidprogramming.com/tutorial/JAVA-Runtime-class-130
• http://jrat.sourceforge.net/
• http://docs.oracle.com/javase/7/docs/api/java/lang/Runtime.html

You can learn the amount of memory your Java UDx needs using several methods. For example, your code can use Java's Runtime class to get an estimate of the total memory it has allocated and then log the value (see Writing Messages to the Log File for details). If you have multiple Java UDxs in your database, set the jvm pool memory size based on the UDx that uses the most memory.

=========================
Also you can try some code quality tools for java like SONAR. Sometimes they really improves and performance too, not just a code quality.
http://en.wikipedia.org/wiki/List_of_tools_for_static_code_analysis#Java
=========================
PS
Don't you have Java developers at your company? No one can explain you how to profile a java app? Any developer have to know how to profile a code (otherwise what kind of developer is it? template/google-help-me developer?)

@adam
Have you idea what next directive means exactly:

daniel=> select get_config_parameter('JavaSideProcessMinHeapSizeMB');  get_config_parameter  ----------------------   5  (1 row) 

Daniel_Leybovic

OFFTOPIC

Java so powerful

http://www.quora.com/What-are-some-cool-Java-tricks

10+ years ago, while coding a project in grad school, I happened across a very cool feature that I have never heard mentioned relating to Java. I was implementing a server using RMI (aka Remote Method Invocation). The RMI server was spinning up a thread to execute some operations on behalf of a client. Note: RMI client and RMI server code were executing on separate machines!

Due to a bug in my code, instead of having the RMI server return the result of the thread computation, it returned the thread itself.

The effect?

The thread's computation started executing on the server and completed executing in the RMI client, which means that the executing thread was serialized over the network and then completed its execution.

Serge_Larionoff_1

Hi Adam! We use Informatics plugin which was downloaded from Vertical site about one week ago, so it is quite fresh, I think. I can control the Commit Interval option, it is responsible on how often does commit happen. I have read a manual, it is written there that a value of this parameter should be increased, but no exact numbers were presented. Also there are some memory recommendations, I applied all of them. When jobs are working, I can see using top or nmon that about 30% of memory is still free on my PowerCenter server. I tried to set a Debug option in connection to on, but it only resulted in a huge log - all loaded data also was in log and no additional information was there.

Serge_Larionoff_1

Hi Daniel! Actually I can't control GC at all as PowerCenter is a closed software and Vertica plugin is fully controlled by it. So I thought that maybe plugin' developers are here and could understand what their code is talking about.

Serge_Larionoff_1

Dear colleagues!

Seems to me that I've found a reason why did this mapping fail. I set the Bad File Name option in session and when it failed one record appeared in this file. It had a strange byte "NUL" in date field and the whole field looks like "NUL000-01-30". I've found this record in source and there is a "MAX_DATE" value in this field - "9999.11.11". I created a special Informatica function which changes such dates from year 9999 to year 2999 and session successfully finished. As I read from Vertica manual, Max value for Date type field is extremely large, ~ 25e+15 AD, and my value of course is less than it. But I am not sure about IPC plugin which is used to transfer data from IPC to Vertica. To test max values I made two experiments:
1. I created a test table and tried to insert this 9999 into table by insert query. It passed OK;
2. I created a special mapping which does nothing but select

SELECT TO_DATE ( '99991111', 'yyyymmdd') AS PPN_DT FROM DUAL

and insert it into Vertica test table. It failed with absolutely the same error:

Severity Timestamp Node Thread Message Code Message
ERROR 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 VERTICA_3050 [ERROR] Stop on errors is set and errors reached threshold. Session will fail
ERROR 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR] JDBC writer encountered a general error: Stop on errors is set and errors reached threshold. Session will fail
ERROR 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 JAVA PLUGIN_1762 [ERROR]  at com.vertica.informatica.powerconnect.server.writer.VerticaWriterPartitionDriver.execute(Unknown Source)
ERROR 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 SDKS_38502 Plug-in #445050's target [SL_TEST: Partition 1] failed in method [execute].
INFO 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 WRT_8333 Rolling back all the targets due to fatal session error.
INFO 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 VERTICA_3083 [INFO] Starting Rollback Transaction
INFO 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 WRT_8325 Final rollback executed for the target [sc_SL_TEST] at end of load
ERROR 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 WRT_8081 Writer run terminated. [Error in loading data to target table [SL_TEST: Partition 1]]
INFO 27.08.2014 11:22:26 node01_nhd-etl WRITER_1_*_1 WRT_8168 End loading table [SL_TEST: Partition 1] at: Wed Aug 27 18:22:26 2014

 

 If anybody has an ability to conect to plugin developers, I could share this test mapping as it is very simple and small and could help them to find and fix this bug from a plugin.