public function __call($methodName, $args) {
$timeStart = microtime(TRUE);
$result = call_user_func_array(array($this->controllerInstance, $methodName), $args);
LogHelper::log_notice(t(
'Data Controller execution time for @methodName(): !executionTime',
array('@methodName' => $methodName, '!executionTime' => LogHelper::formatExecutionTime($timeStart))));
return $result;
}
final public function join(JoinController_SourceConfiguration $sourceConfigurationA, JoinController_SourceConfiguration $sourceConfigurationB) {
$timeStart = microtime(TRUE);
$result = $this->joinSourceConfigurations($sourceConfigurationA, $sourceConfigurationB);
LogHelper::log_notice(t(
'@className execution time: !executionTime',
array('@className' => get_class($this), '!executionTime' => LogHelper::formatExecutionTime($timeStart))));
return $result;
}
protected function executeQueryStatement(DataControllerCallContext $callcontext, DataSourceMetaData $datasource, $sql, __SQLDataSourceHandler__AbstractQueryCallbackProxy $callbackInstance) {
$result = NULL;
if (self::$STATEMENT_EXECUTION_MODE == self::STATEMENT_EXECUTION_MODE__PROCEED) {
$connection = $this->getConnection($datasource);
$timeStart = microtime(TRUE);
$result = $this->getExtension('executeQueryStatement')->execute($this, $callcontext, $connection, $sql, $callbackInstance);
LogHelper::log_notice(t('Database execution time: !executionTime', array('!executionTime' => LogHelper::formatExecutionTime($timeStart))));
}
return $result;
}
protected function loadMetaModel(AbstractMetaModel $metamodel) {
$metaModelName = get_class($this);
LogHelper::log_notice(t('Loading @metamodelName ...', array('@metamodelName' => $metaModelName)));
$metamodelTimeStart = microtime(TRUE);
$metamodelMemoryUsage = memory_get_usage();
if (isset($this->loaders)) {
// preparing each loader for load operation
foreach ($this->loaders as $priority => $loaders) {
foreach ($loaders as $loader) {
$loader->prepare($metamodel);
}
}
$filters = $this->getMetaModelFilters();
foreach ($this->loaders as $priority => $loaders) {
foreach ($loaders as $loader) {
$loaderClassName = get_class($loader);
$loaderTimeStart = microtime(TRUE);
$loader->load($metamodel, $filters);
LogHelper::log_notice(t(
"'@loaderClassName' Meta Model Loader execution time: !executionTime",
array('@loaderClassName' => $loaderClassName, '!executionTime' => LogHelper::formatExecutionTime($loaderTimeStart))));
}
}
// finalizing loading operation
foreach ($this->loaders as $priority => $loaders) {
foreach ($loaders as $loader) {
$loader->finalize($metamodel);
}
}
}
LogHelper::log_notice(t(
'@metamodelName loading time: !loadingTime; Memory consumed: !memoryUsage',
array(
'@metamodelName' => $metaModelName,
'!loadingTime' => LogHelper::formatExecutionTime($metamodelTimeStart),
'!memoryUsage' => (memory_get_usage() - $metamodelMemoryUsage))));
}
public function flush($subsetName = NULL) {
$timeStart = microtime(TRUE);
$result = parent::flush($subsetName);
LogHelper::log_info(t(
"[@cacheType] Execution time for@successFlag cache flush time is !executionTime",
array(
'@cacheType' => $this->getCacheType(),
'!executionTime' => LogHelper::formatExecutionTime($timeStart),
'@successFlag' => t(($result === FALSE) ? (' ' . t('UNSUCCESSFUL')) : ''))));
return $result;
}
public function parse(AbstractDataProvider $dataProvider, array $dataSubmitters = NULL) {
$skippedRecordCount = 0;
$loadedRecordCount = 0;
$timeStart = microtime(TRUE);
if ($dataProvider->openResource()) {
LogHelper::log_notice(t(
'Parsing @limitRecordCount records. Skipping first @skipRecordCount records (memory usage: @memoryUsed) ...',
array(
'@skipRecordCount' => $this->skipRecordCount,
'@limitRecordCount' => (isset($this->limitRecordCount) ? $this->limitRecordCount : t('all')),
'@memoryUsed' => memory_get_usage())));
try {
if ($this->initializeProcessing($dataSubmitters)) {
// preparing list of columns
$this->prepareMetaData($dataProvider, $dataSubmitters);
$metadataColumnCount = $this->metadata->getColumnCount(FALSE, TRUE);
if ((!isset($this->limitRecordCount) || ($this->limitRecordCount > 0))
&& $this->executeBeforeProcessingRecords($dataSubmitters, $dataProvider)) {
// processing records
$fileProcessedCompletely = FALSE;
while (!isset($this->limitRecordCount) || ($loadedRecordCount < $this->limitRecordCount)) {
$dataProvider->startReading();
$record = $this->parseNextRecord($dataProvider, $dataSubmitters);
// number of loaded columns should match number of columns in meta data
if (isset($record)) {
$attempt = 1;
while (TRUE) {
$recordColumnCount = count($record);
if ($recordColumnCount == $metadataColumnCount) {
break;
}
else {
if ($attempt > self::$MAX_ATTEMPTS_TO_RESOLVE_PARSING_ISSUES) {
$dataProvider->endReading();
LogHelper::log_debug($this->metadata);
LogHelper::log_debug($record);
throw new DataParserException(t(
'Expected to load values for %metadataColumnCount columns. Loaded %loadedColumnCount [line: %lineNumber]',
array('%metadataColumnCount' => $metadataColumnCount, '%loadedColumnCount' => $recordColumnCount, '%lineNumber' => $dataProvider->getCurrentLineNumber())));
}
$dataProvider->rollbackReading();
$dataProvider->startReading();
$record = $this->parseNextRecord($dataProvider, $dataSubmitters, $attempt);
$attempt++;
}
}
}
$dataProvider->endReading();
// checking if we reached the end
if (!isset($record)) {
$fileProcessedCompletely = TRUE;
break;
}
// skipping required number of records
if ($skippedRecordCount < $this->skipRecordCount) {
$skippedRecordCount++;
continue;
}
$this->postProcessColumnValues($record);
// checking if we need to skip processing the record
$recordNumber = $dataProvider->getCurrentLineNumber();
if ($this->executeBeforeRecordSubmitted($dataSubmitters, $recordNumber, $record)) {
$this->submitRecord($dataSubmitters, $recordNumber, $record);
$this->executeAfterRecordSubmitted($dataSubmitters, $recordNumber, $record);
$loadedRecordCount++;
if (($loadedRecordCount % 1000) == 0) {
LogHelper::log_info(t(
'Processed @recordCount records so far (memory usage: @memoryUsed)',
array('@recordCount' => $loadedRecordCount, '@memoryUsed' => memory_get_usage())));
}
}
}
$this->executeAfterProcessingRecords($dataSubmitters, $fileProcessedCompletely);
}
$this->finishProcessing($dataSubmitters);
}
}
catch (DataParserException $e) {
LogHelper::log_warn(t('Place of original exception @file:@line', array('@file' => $e->getFile(), '@line' => $e->getLine())));
try {
$this->abortProcessing($dataSubmitters);
}
catch (Exception $ne) {
// we do not need to rethrow this exception. We need to preserve and rethrow original exception
LogHelper::log_error($ne);
}
try {
$dataProvider->closeResource();
}
catch (Exception $ne) {
// we do not need to rethrow this exception. We need to preserve and rethrow original exception
LogHelper::log_error($ne);
}
throw new IllegalStateException($e->getMessage());
}
catch (Exception $e) {
LogHelper::log_warn(t('Place of original exception @file:@line', array('@file' => $e->getFile(), '@line' => $e->getLine())));
try {
$this->abortProcessing($dataSubmitters);
}
catch (Exception $ne) {
// we do not need to rethrow this exception. We need to preserve and rethrow original exception
LogHelper::log_error($ne);
}
$ise = new IllegalStateException(
ExceptionHelper::getExceptionMessage($e) . t(' [%lineNumber line(s) parsed so far]', array('%lineNumber' => $dataProvider->getCurrentLineNumber())),
0, $e);
try {
$dataProvider->closeResource();
}
catch (Exception $ne) {
// we do not need to rethrow this exception. We need to preserve and rethrow original exception
LogHelper::log_error($ne);
}
throw $ise;
}
$dataProvider->closeResource();
}
LogHelper::log_notice(t(
'Processing @recordCount record(s) took !executionTime',
array('@recordCount' => $loadedRecordCount, '!executionTime' => LogHelper::formatExecutionTime($timeStart))));
return $loadedRecordCount;
}
public function executeStatement(DataSourceMetaData $datasource, $sql) {
$affectedRecordCount = 0;
if (self::$STATEMENT_EXECUTION_MODE == self::STATEMENT_EXECUTION_MODE__PROCEED) {
$connection = $this->getConnection($datasource);
$timeStart = microtime(TRUE);
$affectedRecordCount = $this->getExtension('executeStatement')->execute($this, $connection, $sql);
LogHelper::log_notice(t(
'Database execution time for @statementCount statement(s): !executionTime',
array(
'@statementCount' => count($sql),
'!executionTime' => LogHelper::formatExecutionTime($timeStart))));
}
return $affectedRecordCount;
}
