Skip to content

Commit

Permalink
refactor logging in infer storage pass (apache#9464)
Browse files Browse the repository at this point in the history 
* refactor log message in infer storage

* fix bug. support imperative

* remove common:: prefix

* fix gpu build

* address review comments

* use char* and osstream
  • Loading branch information
@eric-haibin-lin @piiswrong
eric-haibin-lin authored and piiswrong committed Jan 19, 2018
1 parent 55ce97c commit 92d79f2
Show file tree
Hide file tree
Showing 23 changed files with 156 additions and 206 deletions.
63 changes: 63 additions & 0 deletions src/common/utils.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -364,6 +364,50 @@ inline std::string dev_type_string(const int dev_type) {
return "unknown";
}

/*! \brief get string representation of the operator stypes */
inline std::string operator_stype_string(const nnvm::NodeAttrs& attrs,
const int dev_mask,
const std::vector<int>& in_attrs,
const std::vector<int>& out_attrs) {
std::ostringstream os;
os << "operator = " << attrs.op->name
<< "\ninput storage types = [";
for (const int attr : in_attrs) {
os << stype_string(attr) << ", ";
}
os << "]\n"
<< "output storage types = [";
for (const int attr : out_attrs) {
os << stype_string(attr) << ", ";
}
os << "]\n"
<< "params = {";
for (auto kv : attrs.dict) {
os << "\"" << kv.first << "\" : " << kv.second << ", ";
}
os << "}\n"
<< "context.dev_mask = " << dev_type_string(dev_mask);
return os.str();
}

/*! \brief get string representation of the operator */
inline std::string operator_string(const nnvm::NodeAttrs& attrs,
const OpContext& ctx,
const std::vector<NDArray>& inputs,
const std::vector<OpReqType>& req,
const std::vector<NDArray>& outputs) {
std::string result = "";
std::vector<int> in_stypes;
std::vector<int> out_stypes;
in_stypes.reserve(inputs.size());
out_stypes.reserve(outputs.size());
auto xform = [](const NDArray arr) -> int { return arr.storage_type(); };
std::transform(inputs.begin(), inputs.end(), std::back_inserter(in_stypes), xform);
std::transform(outputs.begin(), outputs.end(), std::back_inserter(out_stypes), xform);
result += operator_stype_string(attrs, ctx.run_ctx.ctx.dev_mask(), in_stypes, out_stypes);
return result;
}

/*! \brief log message once. Intended for storage fallback warning messages. */
inline void LogOnce(const std::string& message) {
typedef dmlc::ThreadLocalStore<std::unordered_set<std::string>> LogStore;
Expand All @@ -374,6 +418,25 @@ inline void LogOnce(const std::string& message) {
}
}

/*! \brief log storage fallback event
*/
inline void LogStorageFallback(const nnvm::NodeAttrs& attrs,
const int dev_mask,
const std::vector<int>* in_attrs,
const std::vector<int>* out_attrs) {
static bool log = dmlc::GetEnv("MXNET_STORAGE_FALLBACK_LOG_VERBOSE", true);
if (!log) return;
const std::string op_str = operator_stype_string(attrs, dev_mask, *in_attrs, *out_attrs);
std::ostringstream os;
const char* warning = "\nThe operator with default storage type will be dispatched "
"for execution. You're seeing this warning message because the operator above is unable "
"to process the given ndarrays with specified storage types, context and parameter. "
"Temporary dense ndarrays are generated in order to execute the operator. "
"You can set environment variable MXNET_STORAGE_FALLBACK_LOG_VERBOSE to "
"0 to suppress this warning.";
os << "\nStorage type fallback detected:\n" << op_str << warning;
LogOnce(os.str());
}

// heuristic to dermine number of threads per GPU
inline int GetNumThreadPerGPU() {
Expand Down
11 changes: 9 additions & 2 deletions src/executor/infer_graph_attr_pass.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,7 +50,15 @@ bool ApplyOpInferAttr<int, FInferStorageType>(const nnvm::Graph& g,
std::vector<int>* out_attrs,
DispatchMode* dispatch_mode) {
const DevMaskVector& dev_masks = g.GetAttr<DevMaskVector>("dev_mask");
return finfer(attrs, dev_masks[nid], dispatch_mode, in_attrs, out_attrs);
const bool success = finfer(attrs, dev_masks[nid], dispatch_mode, in_attrs, out_attrs);
if (!success) {
LOG(FATAL) << "Operator not implemented: "
<< common::operator_stype_string(attrs, dev_masks[nid], *in_attrs, *out_attrs);
}
if (*dispatch_mode == DispatchMode::kFComputeFallback) {
common::LogStorageFallback(attrs, dev_masks[nid], in_attrs, out_attrs);
}
return true;
}

/*!\brief
Expand Down Expand Up @@ -357,7 +365,6 @@ inline bool DefaultStorageType(const nnvm::NodeAttrs& attrs,
if (*dispatch_mode == DispatchMode::kUndefined) {
if (fallback) {
*dispatch_mode = DispatchMode::kFComputeFallback;
op::LogStorageFallback(attrs, dev_mask, iattr, oattr);
} else {
*dispatch_mode = DispatchMode::kFCompute;
}
Expand Down
16 changes: 11 additions & 5 deletions src/imperative/imperative_utils.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -138,15 +138,21 @@ inline void SetShapeType(const Context& ctx,
for (auto& i : outputs) {
out_storage_types.push_back(i->storage_type());
}
bool infer_stype_success;
if (inferstorage.count(attrs.op)) {
CHECK(inferstorage[attrs.op](attrs, ctx.dev_mask(), dispatch_mode,
&in_storage_types, &out_storage_types));
infer_stype_success = inferstorage[attrs.op](attrs, ctx.dev_mask(), dispatch_mode,
&in_storage_types, &out_storage_types);
} else {
// if infer storage attr is not present, apply the default infer storage function
bool success = exec::DefaultStorageType(attrs, ctx.dev_mask(), dispatch_mode,
&in_storage_types, &out_storage_types);
CHECK(success);
infer_stype_success = exec::DefaultStorageType(attrs, ctx.dev_mask(), dispatch_mode,
&in_storage_types, &out_storage_types);
}
CHECK(infer_stype_success) << "Operator not implemented: "
<< common::operator_stype_string(attrs, ctx.dev_mask(), in_storage_types, out_storage_types);
if (*dispatch_mode == DispatchMode::kFComputeFallback) {
common::LogStorageFallback(attrs, ctx.dev_mask(), &in_storage_types, &out_storage_types);
}

CHECK_EQ(out_storage_types.size(), outputs.size());
CHECK(*dispatch_mode != DispatchMode::kUndefined);

Expand Down
70 changes: 9 additions & 61 deletions src/operator/operator_common.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -350,11 +350,12 @@ inline bool storage_type_assign(StorageTypeVector* stypes,

/*! \brief update the stype vector to default storage and dispatch_mode to fallback
*/
inline void dispatch_fallback(StorageTypeVector* stypes, DispatchMode* dispatch) {
inline bool dispatch_fallback(StorageTypeVector* stypes, DispatchMode* dispatch) {
for (auto& stype : *stypes) {
type_assign(&stype, kDefaultStorage);
}
DISPATCH_MODE_ASSIGN_CHECK(dispatch, 0, DispatchMode::kFComputeFallback);
return true;
}

// make a new node with operator op_name. Inputs are not filled.
Expand Down Expand Up @@ -479,66 +480,13 @@ inline void ParamParser(nnvm::NodeAttrs* attrs) {
<< ") == " << param << ".shape[0] (" << rsp.shape()[0] << ")."; \
}

/*! \brief get string representation of the operator stypes */
inline std::string operator_stype_string(const nnvm::NodeAttrs& attrs,
const int dev_mask,
const std::vector<int>& in_attrs,
const std::vector<int>& out_attrs) {
std::string result = "";
result += "operator = " + attrs.op->name + "\n";
result += "input storage types = [";
for (const auto attr : in_attrs) {
result += common::stype_string(attr) + ", ";
}
result += "]\n";
result += "output storage types = [";
for (const auto attr : out_attrs) {
result += common::stype_string(attr) + ", ";
}
result += "]\n";
result += "params = {";
for (auto kv : attrs.dict) {
result += "\"" + kv.first + "\" : " + kv.second + ", ";
}
result += "}\n";
result += "context.dev_mask = " + common::dev_type_string(dev_mask);
return result;
}

/*! \brief get string representation of the operator */
inline std::string operator_string(const nnvm::NodeAttrs& attrs,
const OpContext& ctx,
const std::vector<NDArray>& inputs,
const std::vector<OpReqType>& req,
const std::vector<NDArray>& outputs) {
std::string result = "";
std::vector<int> in_stypes;
std::vector<int> out_stypes;
auto xform = [](const NDArray arr) -> int { return arr.storage_type(); };
std::transform(inputs.begin(), inputs.end(), std::back_inserter(in_stypes), xform);
std::transform(outputs.begin(), outputs.end(), std::back_inserter(out_stypes), xform);
result += operator_stype_string(attrs, ctx.run_ctx.ctx.dev_mask(), in_stypes, out_stypes);
return result;
}

/*! \brief log storage fallback event
*/
inline void LogStorageFallback(const nnvm::NodeAttrs& attrs,
const int dev_mask,
const std::vector<int>* in_attrs,
const std::vector<int>* out_attrs) {
static bool log = dmlc::GetEnv("MXNET_STORAGE_FALLBACK_LOG_VERBOSE", true);
if (!log) return;
const std::string op_str = op::operator_stype_string(attrs, dev_mask, *in_attrs, *out_attrs);
std::ostringstream os;
os << "\nStorage type fallback detected:\n" << op_str
<< "\nThe operator with default storage type will be dispatched for execution. "
<< "You're seeing this warning message because the operator above is unable to "
<< "process the given ndarrays with specified storage types, context and parameter. "
<< "Temporary dense ndarrays are generated in order to execute the operator. "
<< "You can set environment variable "
<< "MXNET_STORAGE_FALLBACK_LOG_VERBOSE to 0 to suppress this warning.";
common::LogOnce(os.str());
inline void LogUnimplementedOp(const nnvm::NodeAttrs& attrs,
const OpContext &ctx,
const std::vector<NDArray> &inputs,
const std::vector<OpReqType> &req,
const std::vector<NDArray> &outputs) {
using common::operator_string;
LOG(FATAL) << "Not implemented: " << operator_string(attrs, ctx, inputs, req, outputs);
}

} // namespace op
Expand Down
13 changes: 6 additions & 7 deletions src/operator/optimizer_op-inl.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -197,7 +197,7 @@ inline void SGDUpdateEx(const nnvm::NodeAttrs& attrs,
NDArray out = outputs[0];
SGDUpdateRspRspImpl<xpu>(param, ctx, inputs[0], inputs[1], req[0], &out);
} else {
LOG(FATAL) << "Not implemented: " << operator_string(attrs, ctx, inputs, req, outputs);
LogUnimplementedOp(attrs, ctx, inputs, req, outputs);
}
}

Expand Down Expand Up @@ -496,10 +496,9 @@ inline bool StdOptStorageType(const nnvm::NodeAttrs& attrs,
}

if (!dispatched) {
dispatch_fallback(out_attrs, dispatch_mode);
LogStorageFallback(attrs, dev_mask, in_attrs, out_attrs);
dispatched = dispatch_fallback(out_attrs, dispatch_mode);
}
return true;
return dispatched;
}

template<int req>
Expand Down Expand Up @@ -584,7 +583,7 @@ inline void SGDMomUpdateEx(const nnvm::NodeAttrs& attrs,
out_stype == kRowSparseStorage) {
SGDMomStdUpdateRspRspDnsImpl<xpu>(param, ctx, weight, grad, mom, req[0], &out);
} else {
LOG(FATAL) << "Not implemented: " << operator_string(attrs, ctx, inputs, req, outputs);
LogUnimplementedOp(attrs, ctx, inputs, req, outputs);
}
}

Expand Down Expand Up @@ -948,7 +947,7 @@ inline void AdamUpdateEx(const nnvm::NodeAttrs& attrs,
AdamStdUpdateRspRspRspImpl<xpu>(param, ctx, inputs[0], inputs[1], inputs[2],
inputs[3], req[0], &out);
} else {
LOG(FATAL) << "Not implemented: " << operator_string(attrs, ctx, inputs, req, outputs);
LogUnimplementedOp(attrs, ctx, inputs, req, outputs);
}
}

Expand Down Expand Up @@ -1343,7 +1342,7 @@ inline void FtrlUpdateEx(const nnvm::NodeAttrs& attrs,
FtrlUpdateRspRspRspImpl<xpu>(param, ctx, inputs[0], inputs[1], inputs[2],
inputs[3], req[0], &out);
} else {
LOG(FATAL) << "Not implemented: " << operator_string(attrs, ctx, inputs, req, outputs);
LogUnimplementedOp(attrs, ctx, inputs, req, outputs);
}
}

Expand Down
11 changes: 3 additions & 8 deletions src/operator/tensor/broadcast_reduce_op.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -374,13 +374,9 @@ inline bool SumOpForwardInferStorageType(const nnvm::NodeAttrs& attrs,
if (!dispatched) {
// If input is csr, but keepdims or exclude is set or summing along a axis
// different from 0 or 1
dispatch_fallback(out_attrs, dispatch_mode);
dispatched = dispatch_fallback(out_attrs, dispatch_mode);
}
if (*dispatch_mode == DispatchMode::kFComputeFallback) {
LogStorageFallback(attrs, dev_mask, in_attrs, out_attrs);
}

return true;
return dispatched;
}

template<typename xpu, typename reducer>
Expand Down Expand Up @@ -683,8 +679,7 @@ void SumOpForwardEx(const nnvm::NodeAttrs& attrs, const OpContext& ctx,
NDArray output = outputs[0];
SumCsrImpl<xpu, normalize>(attrs, s, ctx, inputs[0], req[0], &output);
} else {
LOG(FATAL) << "Not implemented: "
<< operator_string(attrs, ctx, inputs, req, outputs);
LogUnimplementedOp(attrs, ctx, inputs, req, outputs);
}
}

Expand Down
6 changes: 1 addition & 5 deletions src/operator/tensor/cast_storage-inl.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -397,11 +397,7 @@ inline bool CastStorageInferStorageType(const nnvm::NodeAttrs& attrs,
dispatched = storage_type_assign(out_attrs, param_stype,
dispatch_mode, DispatchMode::kFComputeEx);
}
if (!dispatched) {
LOG(FATAL) << "Not implemented: "
<< operator_stype_string(attrs, dev_mask, *in_attrs, *out_attrs);
}
return true;
return dispatched;
}

template<typename xpu>
Expand Down
16 changes: 6 additions & 10 deletions src/operator/tensor/dot-inl.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -244,12 +244,9 @@ inline bool DotForwardInferStorageType(const nnvm::NodeAttrs& attrs,
dispatch_ex);
}
if (!dispatched) {
dispatch_fallback(out_attrs, dispatch_mode);
dispatched = dispatch_fallback(out_attrs, dispatch_mode);
}
if (static_cast<DispatchMode>(*dispatch_mode) == DispatchMode::kFComputeFallback) {
LogStorageFallback(attrs, dev_mask, in_attrs, out_attrs);
}
return true;
return dispatched;
}

inline bool DotBackwardInferStorageType(const nnvm::NodeAttrs& attrs,
Expand Down Expand Up @@ -294,10 +291,9 @@ inline bool DotBackwardInferStorageType(const nnvm::NodeAttrs& attrs,
}
}
if (!dispatched) {
dispatch_fallback(out_attrs, dispatch_mode);
LogStorageFallback(attrs, dev_mask, in_attrs, out_attrs);
dispatched = dispatch_fallback(out_attrs, dispatch_mode);
}
return true;
return dispatched;
}

/*!
Expand Down Expand Up @@ -1070,7 +1066,7 @@ void DotForwardEx(const nnvm::NodeAttrs& attrs,
NDArray ret = outputs[0];
DotDnsCsrCsrImpl<xpu>(ctx, inputs[0].data(), inputs[1], req[0], &ret);
} else {
LOG(FATAL) << "Not implemented: " << operator_string(attrs, ctx, inputs, req, outputs);
LogUnimplementedOp(attrs, ctx, inputs, req, outputs);
}
}

Expand Down Expand Up @@ -1112,7 +1108,7 @@ void DotBackwardEx(const nnvm::NodeAttrs& attrs,
TBlob ret = outputs[1].data();
DotCsrRspDnsImpl(ctx, xpu(), inputs[1], inputs[0], req[1], !param.transpose_a, &ret);
} else {
LOG(FATAL) << "Not implemented: " << operator_string(attrs, ctx, inputs, req, outputs);
LogUnimplementedOp(attrs, ctx, inputs, req, outputs);
}
}

Expand Down
14 changes: 4 additions & 10 deletions src/operator/tensor/elemwise_binary_op.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -46,12 +46,9 @@ bool ElemwiseBinaryOp::SparseSparseWithDenseResult(const nnvm::NodeAttrs& attrs,
dispatched = storage_type_assign(&out_stype, kDefaultStorage, dispatch_mode, dispatch_ex);
}
if (!dispatched) {
dispatch_fallback(out_attrs, dispatch_mode);
dispatched = dispatch_fallback(out_attrs, dispatch_mode);
}
if (*dispatch_mode == DispatchMode::kFComputeFallback) {
LogStorageFallback(attrs, dev_mask, in_attrs, out_attrs);
}
return true;
return dispatched;
}

bool ElemwiseBinaryOp::BackwardUseInStorageType(const nnvm::NodeAttrs& attrs,
Expand All @@ -78,12 +75,9 @@ bool ElemwiseBinaryOp::BackwardUseInStorageType(const nnvm::NodeAttrs& attrs,
}
}
if (!dispatched) {
dispatch_fallback(out_attrs, dispatch_mode);
}
if (*dispatch_mode == DispatchMode::kFComputeFallback) {
LogStorageFallback(attrs, dev_mask, in_attrs, out_attrs);
dispatched = dispatch_fallback(out_attrs, dispatch_mode);
}
return true;
return dispatched;
}

} // namespace op
Expand Down
Loading

0 comments on commit 92d79f2

Please sign in to comment.