DWH - ETL Issues

david.hahn1 · January 12, 2021, 3:15pm

Hey all, hope you’re doing well. Since the new year I’ve noticed our play counts not being updated. Investigating the DWH logs, I found this error related to not being able to log to the etl_log table.

Any hints as to where to look next to remedy this would be appreciated. I’m inclined to try to truncate the etl_log table, but I’m not sure why the dwh system is not handling this on its own.

Hopefully @jess could lend a hand here

2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 
15.27.10 by buildguy) : Error running job entry 'job' :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : org.pentaho.di.core.exception.KettleJobException:
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Unable to begin processing by logging start in logtable etl_log
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Unable to write log record to log table etl_log
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Error inserting/updating row
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Deadlock found when trying to get lock; try restarting transaction
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.Job.beginProcessing(Job.java:874)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.entries.job.JobEntryJob.execute(JobEntryJob.java:786)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.Job.execute(Job.java:503)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.Job.execute(Job.java:642)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.Job.execute(Job.java:642)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.Job.execute(Job.java:642)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.Job.execute(Job.java:420)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.entries.job.JobEntryJobRunner.run(JobEntryJobRunner.java:63)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at java.lang.Thread.run(Thread.java:748)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Caused by: org.pentaho.di.core.exception.KettleDatabaseException:
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Unable to write log record to log table etl_log
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Error inserting/updating row
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Deadlock found when trying to get lock; try restarting transaction
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.core.database.Database.writeLogRecord(Database.java:3617)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.job.Job.beginProcessing(Job.java:827)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         ... 8 more
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Caused by: org.pentaho.di.core.exception.KettleDatabaseException:
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Error inserting/updating row
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Deadlock found when trying to get lock; try restarting transaction
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.core.database.Database.insertRow(Database.java:1415)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.core.database.Database.insertRow(Database.java:1329)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.core.database.Database.insertRow(Database.java:1317)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.core.database.Database.insertRow(Database.java:1300)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.core.database.Database.insertRow(Database.java:1261)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at org.pentaho.di.core.database.Database.writeLogRecord(Database.java:3613)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         ... 9 more
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) : Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at java.lang.reflect.Constructor.newInstance(Constructor.java:527)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at com.mysql.jdbc.Util.handleNewInstance(Util.java:389)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at com.mysql.jdbc.Util.getInstance(Util.java:372)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987)
2021/01/12 01:00:09 - Run kjbVar job - ERROR (version 4.2.1-stable, build 15952 from 2011-10-25 15.27.10 by buildguy) :         at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3835)

jess · January 12, 2021, 3:34pm

Hi @david.hahn1,

I see you already found Year 2021 analytics problem. This is more for the benefit of other searches.

A version where this is fixed is ready. I’ll be announcing it later today.

Cheers

david.hahn1 · January 12, 2021, 3:45pm

Yes, I did see that, thank you. I’ll await your announcement. In the mean time, is the fix proposed in the previous thread valid or are there other areas where this should be fixed as well?

jess · January 12, 2021, 3:53pm

Hi @david.hahn1,

The fix is valid and no other changes are needed for this particular issue.

t-saito · January 12, 2021, 4:43pm

Hello @david.hahn1,

The “Year 2021 analytics problem” doesn’t print an error message.
Therefore, we feel that the playback count is not updated even though no error has occurred.

I faced the same problem as you.
As the number of records in the etl_log table increases, the following errors occur more frequently:

Unable to write log record to log table etl_log
Error inserting/updating row
Deadlock found when trying to get lock; try restarting transaction

I guess that database server performance is insufficient.
So that, I have taken the following measures:

Increase CPU cores of our database server.
Increase value of “innodb_buffer_pool_size” (MySQL/MariaDB setting).
Increase value of “key_buffer_size” (MySQL/MariaDB setting).
Delete old records in etl_log table.

Note that, deleting etl_log records might affect long-term analytics.

Now, our dabase server works normally.

Regards,

david.hahn1 · January 12, 2021, 8:14pm

Hey @jess and @t-saito

I made the prescribed changes in the two etl files from that other thread and ran the kaltura-run-dwh.sh script manually. I don’t see that the play counts were updated, though.

I get 0 results from…
select * from kalturadw.dwh_fact_events where event_date_id >=20210101

I’m wondering if the plays that happened between 12/31 and today are lost? Should I play a few videos and see if the play counts make it through the dwh process?

Thanks for any guidance --dave

t-saito · January 12, 2021, 10:02pm

Hello @david.hahn1,

At this problem, Kaltura system considers log-files after January 1st to be processed successfully.
Therefore, in “kalturadw.dwh_fact_plays” and “kalturadw.dwh_fact_bandwidth_usage” tables, new records may be inserted according to statistics data.

In order to check the problem is resolved, it is easier to play video and create new logs.

If you want to revive the playback counts between January 1st and today, the following steps will be helpful.

At first, delete the statistical data after January 1st from database.

mysql> use kalturadw;
mysql> delete from dwh_fact_events where event_date_id>=20210101;
mysql> delete from dwh_fact_plays where play_date_id>=20210101;
mysql> delete from dwh_fact_bandwidth_usage where activity_date_id>=20210101;

Next, in table “kalturadw_ds.done_cycles”, find “cycle_id” values of cycles that occurred after January 1st.
The values of “insert_time” and “transfer_time” will be helpful.
Then, delete cycle records generated after January 1st from the “done_cycles” table.

Next, in “kalturadw_ds.files” table, delete records related the deleted cycles.
The values of “cycle_id” will be helpful.

In “/opt/kaltura/dwh/cycles/original” and “/opt/kaltura/dwh/cycles/process” directories, delete sub-directories related the deleted cycles.

When “/opt/kaltura/dwh/etlsource/execute/etl_hourly.sh” is executed, new records will be inserted to “dwh_fact_events”, “dwh_fact_plays”, and “dwh_fact_bandwidth_usage” tables according to non-processed log-files in “/opt/kaltura/web/logs” directory.
Then, “dwh_plays_views_sync.sh” will update playback counts of each media entry (and bandwidth usage, etc.) according to the tables.

Regards,

david.hahn1 · January 13, 2021, 7:02pm

Hey @t-saito

I’ve decided not to try to salvage the plays between January 1 and now.

I am still not getting any plays updated, though and I’m not sure why.

I’ve edited the files in my installation as I’m not in a position to upgrade at this point. I don’t see any overt errors in the dwh log files I’ve examined.

I do not see any new facts inserted into kalturadw.dwh_fact_events, which i think is there the trail leaves me.

I do see entries for files inserted into kalturadw_ds.files.

I did play a video yesterday so I expected to see at least one video increment it’s play count.

Any help you or @jess can lend would be much appreciated!

david.hahn1 · January 13, 2021, 7:37pm

OK, I may have lied about no errors. I did see a javascript parsing error related to the process_file.kjb file. I looked at the changes in the source and compared it to what I had edited and I I had an extra */ in there. I’ve corrected it and will monitor in the next hour when the hourly job runs. Stay tuned if you’re interested!

t-saito · January 14, 2021, 1:36am

Hello @david.hahn1,

I’m looking forward to the results.

Note that, the Kaltura DWH does not process log-files already stored in table “kalturadw_ds.files”.
Returning processed log-files to an unprocessed state can be tedious.

Regards,

david.hahn1 · January 14, 2021, 4:19pm

The plays are updating this morning. I think we’re good here. Thanks for all your assistance!