/* DataFlash Remote(via MAVLink) logging */ #include "DataFlash_MAVLink.h" #if DATAFLASH_MAVLINK_SUPPORT #include "LogStructure.h" #define REMOTE_LOG_DEBUGGING 0 #if REMOTE_LOG_DEBUGGING #include # define Debug(fmt, args ...) do {printf("%s:%d: " fmt "\n", __FUNCTION__, __LINE__, ## args); hal.scheduler->delay(1); } while(0) #else # define Debug(fmt, args ...) #endif #include extern const AP_HAL::HAL& hal; // initialisation void DataFlash_MAVLink::Init() { DataFlash_Backend::Init(); _blocks = NULL; while (_blockcount >= 8) { // 8 is a *magic* number _blocks = (struct dm_block *) malloc(_blockcount * sizeof(_blocks[0])); if (_blocks != NULL) { break; } _blockcount /= 2; } if (_blocks == NULL) { return; } free_all_blocks(); stats_init(); _initialised = true; _logging_started = true; // in actual fact, we throw away // everything until a client connects. // This stops calls to start_new_log from // the vehicles } bool DataFlash_MAVLink::logging_failed() const { return !_sending_to_client; } uint16_t DataFlash_MAVLink::bufferspace_available() { return (_blockcount_free * 200 + remaining_space_in_current_block()); } uint8_t DataFlash_MAVLink::remaining_space_in_current_block() { // note that _current_block *could* be NULL ATM. return (MAVLINK_MSG_REMOTE_LOG_DATA_BLOCK_FIELD_DATA_LEN - _latest_block_len); } void DataFlash_MAVLink::enqueue_block(dm_block_queue_t &queue, struct dm_block *block) { if (queue.youngest != NULL) { queue.youngest->next = block; } else { queue.oldest = block; } queue.youngest = block; } struct DataFlash_MAVLink::dm_block *DataFlash_MAVLink::dequeue_seqno(DataFlash_MAVLink::dm_block_queue_t &queue, uint32_t seqno) { struct dm_block *prev = NULL; for (struct dm_block *block=queue.oldest; block != NULL; block=block->next) { if (block->seqno == seqno) { if (prev == NULL) { if (queue.youngest == queue.oldest) { queue.oldest = NULL; queue.youngest = NULL; } else { queue.oldest = block->next; } } else { if (queue.youngest == block) { queue.youngest = prev; } prev->next = block->next; } block->next = NULL; return block; } prev = block; } return NULL; } bool DataFlash_MAVLink::free_seqno_from_queue(uint32_t seqno, dm_block_queue_t &queue) { struct dm_block *block = dequeue_seqno(queue, seqno); if (block != NULL) { block->next = _blocks_free; _blocks_free = block; _blockcount_free++; // comment me out to expose a bug! return true; } return false; } /* Write a block of data at current offset */ // DM_write: 70734 events, 0 overruns, 167806us elapsed, 2us avg, min 1us max 34us 0.620us rms bool DataFlash_MAVLink::WritePrioritisedBlock(const void *pBuffer, uint16_t size, bool is_critical) { if (!_initialised || !_sending_to_client || !_writes_enabled) { return false; } if (! WriteBlockCheckStartupMessages()) { return false; } if (bufferspace_available() < size) { if (_startup_messagewriter->finished()) { // do not count the startup packets as being dropped... dropped++; } return false; } uint16_t copied = 0; while (copied < size) { if (_current_block == NULL) { _current_block = next_block(); if (_current_block == NULL) { // should not happen - there's a sanity check above internal_error(); return false; } } uint16_t remaining_to_copy = size - copied; uint16_t _curr_remaining = remaining_space_in_current_block(); uint16_t to_copy = (remaining_to_copy > _curr_remaining) ? _curr_remaining : remaining_to_copy; memcpy(&(_current_block->buf[_latest_block_len]), &((const uint8_t *)pBuffer)[copied], to_copy); copied += to_copy; _latest_block_len += to_copy; if (_latest_block_len == MAVLINK_MSG_REMOTE_LOG_DATA_BLOCK_FIELD_DATA_LEN) { //block full, mark it to be sent: enqueue_block(_blocks_pending, _current_block); _current_block = next_block(); } } if (!_writing_startup_messages) { // push_log_blocks(); } return true; } //Get a free block struct DataFlash_MAVLink::dm_block *DataFlash_MAVLink::next_block() { DataFlash_MAVLink::dm_block *ret = _blocks_free; if (ret != NULL) { _blocks_free = ret->next; _blockcount_free--; ret->seqno = _next_seq_num++; ret->last_sent = 0; ret->next = NULL; _latest_block_len = 0; } return ret; } void DataFlash_MAVLink::free_all_blocks() { _blocks_free = NULL; _current_block = NULL; _blocks_pending.sent_count = 0; _blocks_pending.oldest = _blocks_pending.youngest = NULL; _blocks_retry.sent_count = 0; _blocks_retry.oldest = _blocks_retry.youngest = NULL; _blocks_sent.sent_count = 0; _blocks_sent.oldest = _blocks_sent.youngest = NULL; // add blocks to the free stack: for(uint8_t i=0; i < _blockcount; i++) { _blocks[i].next = _blocks_free; _blocks_free = &_blocks[i]; // this value doesn't really matter, but it stops valgrind // complaining when acking blocks (we check seqno before // state). Also, when we receive ACKs we check seqno, and we // want to ack the *real* block zero! _blocks[i].seqno = 9876543; } _blockcount_free = _blockcount; _latest_block_len = 0; } void DataFlash_MAVLink::stop_logging() { if (_sending_to_client) { _sending_to_client = false; _last_response_time = AP_HAL::millis(); } } void DataFlash_MAVLink::handle_ack(mavlink_channel_t chan, mavlink_message_t* msg, uint32_t seqno) { if (!_initialised) { return; } if(seqno == MAV_REMOTE_LOG_DATA_BLOCK_STOP) { Debug("Received stop-logging packet"); stop_logging(); return; } if(seqno == MAV_REMOTE_LOG_DATA_BLOCK_START) { if (!_sending_to_client) { Debug("Starting New Log"); free_all_blocks(); // _current_block = next_block(); // if (_current_block == NULL) { // Debug("No free blocks?!!!\n"); // return; // } stats_init(); _sending_to_client = true; _target_system_id = msg->sysid; _target_component_id = msg->compid; _chan = chan; _next_seq_num = 0; start_new_log_reset_variables(); _last_response_time = AP_HAL::millis(); Debug("Target: (%u/%u)", _target_system_id, _target_component_id); } return; } // check SENT blocks (VERY likely to be first on the list): if (free_seqno_from_queue(seqno, _blocks_sent)) { // celebrate _last_response_time = AP_HAL::millis(); } else if(free_seqno_from_queue(seqno, _blocks_retry)) { // party _last_response_time = AP_HAL::millis(); } else { // probably acked already and put on the free list. } } void DataFlash_MAVLink::remote_log_block_status_msg(mavlink_channel_t chan, mavlink_message_t* msg) { mavlink_remote_log_block_status_t packet; mavlink_msg_remote_log_block_status_decode(msg, &packet); if(packet.status == 0){ handle_retry(packet.seqno); } else{ handle_ack(chan, msg, packet.seqno); } } void DataFlash_MAVLink::handle_retry(uint32_t seqno) { if (!_initialised || !_sending_to_client) { return; } struct dm_block *victim = dequeue_seqno(_blocks_sent, seqno); if (victim != NULL) { _last_response_time = AP_HAL::millis(); enqueue_block(_blocks_retry, victim); } } void DataFlash_MAVLink::set_channel(mavlink_channel_t chan) { _chan = chan; } void DataFlash_MAVLink::internal_error() { internal_errors++; DataFlash_Backend::internal_error(); } void DataFlash_MAVLink::stats_init() { dropped = 0; internal_errors = 0; stats.resends = 0; stats_reset(); } void DataFlash_MAVLink::stats_reset() { stats.state_free = 0; stats.state_free_min = -1; // unsigned wrap stats.state_free_max = 0; stats.state_pending = 0; stats.state_pending_min = -1; // unsigned wrap stats.state_pending_max = 0; stats.state_retry = 0; stats.state_retry_min = -1; // unsigned wrap stats.state_retry_max = 0; stats.state_sent = 0; stats.state_sent_min = -1; // unsigned wrap stats.state_sent_max = 0; stats.collection_count = 0; } void DataFlash_MAVLink::Log_Write_DF_MAV(DataFlash_MAVLink &df) { if (df.stats.collection_count == 0) { return; } struct log_DF_MAV_Stats pkt = { LOG_PACKET_HEADER_INIT(LOG_DF_MAV_STATS), timestamp : AP_HAL::millis(), seqno : df._next_seq_num-1, dropped : df.dropped, retries : df._blocks_retry.sent_count, resends : df.stats.resends, internal_errors : df.internal_errors, state_free_avg : (uint8_t)(df.stats.state_free/df.stats.collection_count), state_free_min : df.stats.state_free_min, state_free_max : df.stats.state_free_max, state_pending_avg : (uint8_t)(df.stats.state_pending/df.stats.collection_count), state_pending_min : df.stats.state_pending_min, state_pending_max : df.stats.state_pending_max, state_sent_avg : (uint8_t)(df.stats.state_sent/df.stats.collection_count), state_sent_min : df.stats.state_sent_min, state_sent_max : df.stats.state_sent_max, // state_retry_avg : (uint8_t)(df.stats.state_retry/df.stats.collection_count), // state_retry_min : df.stats.state_retry_min, // state_retry_max : df.stats.state_retry_max }; WriteBlock(&pkt,sizeof(pkt)); } void DataFlash_MAVLink::stats_log() { if (!_initialised || !_logging_started) { return; } if (stats.collection_count == 0) { return; } Log_Write_DF_MAV(*this); #if REMOTE_LOG_DEBUGGING printf("D:%d Retry:%d Resent:%d E:%d SF:%d/%d/%d SP:%d/%d/%d SS:%d/%d/%d SR:%d/%d/%d\n", dropped, _blocks_retry.sent_count, stats.resends, internal_errors, stats.state_free_min, stats.state_free_max, stats.state_free/stats.collection_count, stats.state_pending_min, stats.state_pending_max, stats.state_pending/stats.collection_count, stats.state_sent_min, stats.state_sent_max, stats.state_sent/stats.collection_count, stats.state_retry_min, stats.state_retry_max, stats.state_retry/stats.collection_count ); #endif stats_reset(); } uint8_t DataFlash_MAVLink::stack_size(struct dm_block *stack) { uint8_t ret = 0; for (struct dm_block *block=stack; block != NULL; block=block->next) { ret++; } return ret; } uint8_t DataFlash_MAVLink::queue_size(dm_block_queue_t queue) { return stack_size(queue.oldest); } void DataFlash_MAVLink::stats_collect() { if (!_initialised || !_logging_started) { return; } uint8_t pending = queue_size(_blocks_pending); uint8_t sent = queue_size(_blocks_sent); uint8_t retry = queue_size(_blocks_retry); uint8_t sfree = stack_size(_blocks_free); if (sfree != _blockcount_free) { internal_error(); } stats.state_pending += pending; stats.state_sent += sent; stats.state_free += sfree; stats.state_retry += retry; if (pending < stats.state_pending_min) { stats.state_pending_min = pending; } if (pending > stats.state_pending_max) { stats.state_pending_max = pending; } if (retry < stats.state_retry_min) { stats.state_retry_min = retry; } if (retry > stats.state_retry_max) { stats.state_retry_max = retry; } if (sent < stats.state_sent_min) { stats.state_sent_min = sent; } if (sent > stats.state_sent_max) { stats.state_sent_max = sent; } if (sfree < stats.state_free_min) { stats.state_free_min = sfree; } if (sfree > stats.state_free_max) { stats.state_free_max = sfree; } stats.collection_count++; } /* while we "successfully" send log blocks from a queue, move them to * the sent list. DO NOT call this for blocks already sent! */ bool DataFlash_MAVLink::send_log_blocks_from_queue(dm_block_queue_t &queue) { uint8_t sent_count = 0; while (queue.oldest != NULL) { if (sent_count++ > _max_blocks_per_send_blocks) { return false; } if (! send_log_block(*queue.oldest)) { return false; } queue.sent_count++; struct DataFlash_MAVLink::dm_block *tmp = dequeue_seqno(queue,queue.oldest->seqno); if (tmp != NULL) { // should never be NULL enqueue_block(_blocks_sent, tmp); } else { internal_error(); } } return true; } void DataFlash_MAVLink::push_log_blocks() { if (!_initialised || !_logging_started ||!_sending_to_client) { return; } DataFlash_Backend::WriteMoreStartupMessages(); if (! send_log_blocks_from_queue(_blocks_retry)) { return; } if (! send_log_blocks_from_queue(_blocks_pending)) { return; } } void DataFlash_MAVLink::do_resends(uint32_t now) { if (!_initialised || !_logging_started ||!_sending_to_client) { return; } uint8_t count_to_send = 5; if (_blockcount < count_to_send) { count_to_send = _blockcount; } uint32_t oldest = now - 100; // 100 milliseconds before resend. Hmm. while (count_to_send-- > 0) { for (struct dm_block *block=_blocks_sent.oldest; block != NULL; block=block->next) { // only want to send blocks every now-and-then: if (block->last_sent < oldest) { if (! send_log_block(*block)) { // failed to send the block; try again later.... return; } stats.resends++; } } } } void DataFlash_MAVLink::periodic_10Hz(const uint32_t now) { do_resends(now); stats_collect(); } void DataFlash_MAVLink::periodic_1Hz(const uint32_t now) { if (_sending_to_client && _last_response_time + 10000 < _last_send_time) { // other end appears to have timed out! Debug("Client timed out"); _sending_to_client = false; return; } stats_log(); } void DataFlash_MAVLink::periodic_fullrate(uint32_t now) { push_log_blocks(); } //TODO: handle full txspace properly bool DataFlash_MAVLink::send_log_block(struct dm_block &block) { mavlink_channel_t chan = mavlink_channel_t(_chan - MAVLINK_COMM_0); if (!_initialised) { return false; } if (!HAVE_PAYLOAD_SPACE(chan, REMOTE_LOG_DATA_BLOCK)) { return false; } if (comm_get_txspace(chan) < 500) { return false; } #if CONFIG_HAL_BOARD == HAL_BOARD_SITL if (rand() < 0.1) { return false; } #endif #if DF_MAVLINK_DISABLE_INTERRUPTS irqstate_t istate = irqsave(); #endif // DM_packing: 267039 events, 0 overruns, 8440834us elapsed, 31us avg, min 31us max 32us 0.488us rms hal.util->perf_begin(_perf_packing); mavlink_message_t msg; mavlink_status_t *chan_status = mavlink_get_channel_status(chan); uint8_t saved_seq = chan_status->current_tx_seq; chan_status->current_tx_seq = mavlink_seq++; // Debug("Sending block (%d)", block.seqno); mavlink_msg_remote_log_data_block_pack(mavlink_system.sysid, MAV_COMP_ID_LOG, &msg, _target_system_id, _target_component_id, block.seqno, block.buf); hal.util->perf_end(_perf_packing); #if DF_MAVLINK_DISABLE_INTERRUPTS irqrestore(istate); #endif block.last_sent = AP_HAL::millis(); chan_status->current_tx_seq = saved_seq; // _last_send_time is set even if we fail to send the packet; if // the txspace is repeatedly chockas we should not add to the // problem and stop attempting to log _last_send_time = AP_HAL::millis(); _mavlink_resend_uart(chan, &msg); return true; } #endif