Show more timing information.

camd.c

@@ -116,10 +116,12 @@ static int camd_recv_cw(struct ts *ts) {
 	}
 
 	if (ts->ecm_cw_log) {
-		ts_LOGf("CW  | CAID: 0x%04x [ %5llu ms ] ( %6llu ms ) ------ IDX: 0x%04x Data: %s\n",
-			ca_id, timeval_diff_msec(&tv1, &tv2),
+		ts_LOGf("CW  | SID 0x%04x CAID: 0x%04x CW_recv: %5llu ms LastKey: %5llu ms Data: %s\n",
+			ts->service_id,
+			ca_id,
+			timeval_diff_msec(&tv1, &tv2),
 			timeval_diff_msec(&last_ts_keyset, &tv2),
-			idx, cw_dump );
+			cw_dump );
 	}
 
 	return 1;

data.h

@@ -220,6 +220,7 @@ struct ts {
 	unsigned int		cw_warn_sec;
 	time_t				cw_last_warn;
 	time_t				cw_next_warn;
+	struct timeval		ecm_change_time;
 
 	unsigned int		pid_report;
 	unsigned int		pid_stats[MAX_PIDS];

process.c

@@ -124,6 +124,8 @@ static void decode_buffer(struct ts *ts, uint8_t *data, int data_len) {
 	struct dvbcsa_bs_batch_s even_pcks[batch_sz + 1];
 	struct dvbcsa_bs_batch_s odd_pcks [batch_sz + 1];
 
+	int scramble_idx_old = 0;
+
 	// Prepare batch structure
 	for (i = 0; i < batch_sz; i++) {
 		uint8_t *ts_packet = data + (i * 188);
@@ -132,6 +134,8 @@ static void decode_buffer(struct ts *ts, uint8_t *data, int data_len) {
 		if (pidmap_get(&ts->pidmap, pid) && ts_packet_is_scrambled(ts_packet)) {
 			if (ts->key.is_valid_cw) {
 				int scramble_idx = ts_packet_get_scrambled(ts_packet);
+				if (!scramble_idx_old)
+					scramble_idx_old = scramble_idx;
 				uint8_t payload_ofs = ts_packet_get_payload_offset(ts_packet);
 				if (scramble_idx == 2) { // scramble_idx 2 == even key
 					even_pcks[even_packets].data = ts_packet + payload_ofs;
@@ -144,6 +148,15 @@ static void decode_buffer(struct ts *ts, uint8_t *data, int data_len) {
 					odd_packets++;
 				}
 				ts_packet_set_not_scrambled(ts_packet);
+				if (scramble_idx_old != scramble_idx) {
+					struct timeval tv;
+					gettimeofday(&tv, NULL);
+					ts_LOGf("CWC | SID 0x%04x ------------ EcmTime: %5llu ms CW_time: %5llu ms\n",
+						ts->service_id,
+						timeval_diff_msec(&ts->ecm_change_time, &tv),
+						timeval_diff_msec(&ts->key.ts_keyset, &tv));
+				}
+				scramble_idx_old = scramble_idx;
 			} else {
 				if (ts->pid_filter)
 					ts_packet_set_pid(ts_packet, 0x1fff);
@@ -307,6 +320,7 @@ void process_packets(struct ts *ts, uint8_t *data, ssize_t data_len) {
 		if (ts->pid_report)
 			ts->pid_stats[pid]++;
 
+
 		ts_pack_shown = 0;
 
 		process_pat(ts, pid, ts_packet);

tables.c

@@ -307,8 +307,15 @@ static void __process_ecm(struct ts *ts, uint16_t pid, uint8_t *ts_packet) {
 	int duplicate = ts_privsec_is_same(ts->ecm, ts->last_ecm);
 	if (duplicate && !ts->is_cw_error)
 		ts->ecm_duplicate_count++;
+	if (!ts->ecm_change_time.tv_sec)
+		gettimeofday(&ts->ecm_change_time, NULL);
 	if (!duplicate || ts->is_cw_error) {
 		if (ts->ecm_cw_log) {
+			struct timeval tv;
+			gettimeofday(&tv, NULL);
+			ts_LOGf("ECC | SID 0x%04x ------------ EcmChng: %5llu ms\n",
+				ts->service_id,
+				timeval_diff_msec(&ts->ecm_change_time, &tv));
 			ts_hex_dump_buf(dump, dump_buf_sz, sec->section_data, min(dump_sz, sec->section_data_len), 0);
 			ts_LOGf("ECM | SID 0x%04x CAID: 0x%04x PID 0x%04x Table: 0x%02x Length: %4d Data: %s..\n",
 				ts->service_id,
@@ -317,6 +324,7 @@ static void __process_ecm(struct ts *ts, uint16_t pid, uint8_t *ts_packet) {
 				sec->table_id,
 				sec->section_data_len,
 				dump);
+			gettimeofday(&ts->ecm_change_time, NULL);
 		}
 		ts->is_cw_error = 0;
 		camd_process_packet(ts, camd_msg_alloc(ECM_MSG, ts->ecm_caid, ts->service_id, sec->section_data, sec->section_data_len));